Arguments to NRF_LOG_DEBUG() sometimes missing in RTT output, SDK 15.3.0.

[Eliot Stock]

I recently migrated from SDK 14.2.0 to SDK 15.3.0 and just noticed that some but not all of my logging is broken. A logging macro call such as this:

NRF_LOG_DEBUG("Output power: %s dBm", (int)m_modem.response);

will log only:

D modem Output power:  dBm

when I expect to see:

D modem Output power: 14 dBm

Is this a known issue? Is there a workaround?

[haakonsh]

Hmm I believe you should use '%d' for decimal integers. Right now it's expecting a string, but you've provided an int. 

Are you sure m_modem.response has a value when you call the NRF_LOG_DEBUG function?

[Eliot Stock]

That value is in fact a string. In previous SDK releases, the cast to (int) was required to prevent a compile warning or error. Is that no longer the case? It seems not. So I now need to go through all my logging and remove them, and it'll work again?

[haakonsh]

I'm reading the definitions for NRF_LOG_DEBUG, it's a bit of a mess, but it seems it takes in uint32_t as arguments, not int nor strings.

NRF_LOG_DEBUG will expand into a function that calls std_n() on line 536 of nrf_log_frontend.c.

There's a comment that hints to our issue: // Proceed only if buffer was successfully preallocated.

Have you set NRF_LOG_ALLOW_OVERFLOW to 1 in sdk_config? I believe the log module will overflow its circular buffer and overwrite the first entries, but this will only happen if NRF_LOG_ALLOW_OVERFLOW is set to 1. Otherwise the log module will skip the last log entry entirely.

From line 78 in nrf_log_frontend.c:

/**

* brief An internal control block of the logger

*

* @note Circular buffer is using never cleared indexes and a mask. It means

* that logger may break when indexes overflows. However, it is quite unlikely.

* With rate of 1000 log entries with 2 parameters per second such situation

* would happen after 12 days.

*/

How often do you invoke NRF_LOG_DEBUG? 

I suggest you try increasing the buffer size of the log module and turning deferred logging on/off.

 

[Eliot Stock]

Yes, NRF_LOG_ALLOW_OVERFLOW was already set to 1. I'm not doing a ton of logging - perhaps 100 NRF_LOG_*() invocations per second at most? And averaging more like 10 per second.

I had NRF_LOG_DEFERRED set to 0, but changing it to 1 hasn't fixed the issue. Neither has increasing both of these:

#define NRF_LOG_BACKEND_RTT_TEMP_BUFFER_SIZE 256

#define SEGGER_RTT_CONFIG_BUFFER_SIZE_DOWN 64

[Eliot Stock]

Any update here? Should I create a private case and add the whole codebase?

[haakonsh]

We're a bit short staffed during the summer vacations, but I'll try to get hold of someone that has worked on the logger module.

[Eliot Stock]

OK cool, thanks.

[Eliot Stock]

Any update on this please? It's been a while.

[Eliot Stock]

haakonsh, how can I make some progress here please? Would a private case with the whole codebase help?