Would nrf_log_frontend_dequeue lose some traces in corner cases even though it is not an overflow case ?

[Vincent Belaïche]

Not something which I have experienced, but rather inferred from reading the code of nRF5_SDK_17.0.2_d674dde/nRF5_SDK_17.0.2_d674dde/components/libraries/log/src/nrf_log_frontend.c:739.

We have this code : 

//Check if end of data is not reached.
if (rd_idx >= m_log_data.wr_idx)
{
   m_log_data.rd_idx = m_log_data.wr_idx;
   return false;
}

The read pointer is progressed after skipping some in progress blocks. This means that when the preparation of these blocks is complete and their in_progress flag is lowered, all the same, they won't ever be passed to the backend, they are lost for ever.

Of course, in real life, since the log flush (calling nrf_log_frontend_dequeue) is either done at once, or in general done by a lower priority RTOS task than that which produces the log matter, then this situation won't happen.

However in principle would it be possible for it to happen ? if so isn't that some sort of bug ?

[Kenneth]

I believe this should be configurable by for instance configure NRF_LOG_ALLOW_OVERFLOW (and indirectly NRF_LOG_DEFERRED and NRF_LOG_BUFSIZE).

If logs are skipped you will see: Logs dropped (count)

[Vincent Belaïche]

I don't think so : 

• concerning NRF_LOG_ALLOW_OVERFLOW, this flag is tested well farther in the same function. Slo when the if (rd_idx >= m_log_data.wr_idx) test is done, NRF_LOG_ALLOW_OVERFLOW has not yet been tested.
• concerning NRF_LOG_DEFERRED that just tells whether  nrf_log_frontend_dequeue is called at once, or by a separate (typically lower priority) task.
  • If you do not have deferred logging, you may have the case if for instance you have task A with lower priority than task B, task A starts some log, so it has some in_process == 1 block opening in the RTT buffer, then task B preempts task A, make the rd_idx >= m_log_data.wr_idx test after all its logs have been processed  by the backend, and therefore I presumes that the packet opened by task A is lost, which is the object of this ticket,
    
  • If you have deferred logging, then this case is possible only if the flush is deferred to a task with higher priority than that of the task producing the log input (which is why I wrote that this problem would not happen in usual conditions)
• Concerning the NRF_LOG_BUFSIZE, anyway whatever the buffer size, if there is some pause in the log source, the backend will get at the end of the logged data, so that does not solve the case either.

[Kenneth]

I will add this to the internal issue reporting for the SDK team, so it may be looked upon for future releases.

Best regards,
Kenneth