Use of NRF_LOG_FLOAT_MARKER with deferred logging leads to bad output or hang

[fkoran]

I have a project based on SDK 15.3

I've set #define NRF_LOG_DEFERRED 1

The project generates a high volume of log output over RTT

NRF_LOG_FLOAT_MARKER is a macro that splits a floating point number into three pieces:

%s - sign string

%d - integer part

%d - fractional part

I've found that if I use NRF_LOG_FLOAT_MARKER in deferred mode, the sign string is usually corrupted into gibberish

Sometimes the MCU will hang at nrf_fprintf_format.c:string_print():115

Changing the sign from a string to a character in nrf_log.h seems to fix this:

/**
* @brief Macro to be used in a formatted string to a pass float number to the log.
*
* Use this macro in a formatted string instead of the %f specifier together with
* @ref NRF_LOG_FLOAT macro.
* Example: NRF_LOG_INFO("My float number" NRF_LOG_FLOAT_MARKER "\r\n", NRF_LOG_FLOAT(f)))
*/
#define NRF_LOG_FLOAT_MARKER "%c%d.%02d"

/**
* @brief Macro for dissecting a float number into two numbers (integer and residuum).
*/
#define NRF_LOG_FLOAT(val) (uint32_t)(((val) < 0 && (val) > -1.0) ? '-' : '+'), \
(int32_t)(val), \
(int32_t)((((val) > 0) ? (val) - (int32_t)(val) \
: (int32_t)(val) - (val))*100)

Posting here in case someone else has this problem or if there's a better workaround

[Jørgen Holmefjord]

Hi,

This looks like it could be related to the limitations mentioned in the documentation:

Using the deferred mode introduces some limitations to the logging mechanism:

• Number of arguments in a formatted string is limited to six.
• All arguments are treated as uint32_t. This results in the following:
  • In certain situations (for example, smaller variables like uint8_t as arguments) the compiler gives a warning and the argument must be masked and cast to uint32_t.
  • The logger cannot handle arguments bigger than 32 bits, so they must be explicitly split up by the user into two separate entries.
• Since the logs are not processed directly, it is risky to pass pointers as arguments, especially to variables that do not have static addresses, for example variables allocated on the stack. By the time the log is processed, the pointer can point to invalid data. The logger provides a mechanism to overcome this issue by enforcing a string that is copied into the internal logger buffer.

Given the last limitation, the following way of logging a temporary string is not recommended:

void foo(void)
{
    char string_on_stack[] = "stack";
    
    //WRONG! by the time the log is processed, variable content will be invalid
    NRF_LOG_INFO("%s",string_on_stack);
}

Instead, use the following way of logging a temporary string:

void foo(void)
{
    char string_on_stack[] = "stack";
    
    //nrf_log_push() copies the string into the logger buffer and returns address from the logger buffer
    NRF_LOG_INFO("%s",NRF_LOG_PUSH(string_on_stack));
}

Can you check if adding "NRF_LOG_PUSH(string_on_stack)" to the code also fix this issue?

Best regards,
Jørgen

[fkoran]

Yes, NRF_LOG_PUSH(string_on_stack) also gets around the issue