nRF5 SDK  v17.0.2
Choose documentation:
 All Data Structures Functions Variables Typedefs Enumerations Enumerator Groups Pages
Logger module

The logger module provides logging capability for your application. It is used by SDK modules and can be also used in the application code. Main features of this library are:

  • Four severity levels - ERROR, WARNING, INFO, and DEBUG.
  • Formatted string (printf-like) log format.
  • Dedicated macro for dumping data.
  • Configurable global severity level.
  • Independent severity level for each module.
  • Enabling and disabling logging per module and globally.
  • Filtering on module instance level.
  • Optional timestamping with time formatting.
  • Optional coloring of the logs for different modules and different severity levels.
  • Prefixing log entries with the module name or instance name, and severity.
  • Deferring of log processing to idle stage.
  • Logging mechanism decoupled from the logger backend.
  • Multiple backends supported.
  • Several backends provided: RTT, UART, console (Command Line Interface), flash (see Flash logger backend).
  • Optional dynamic (run time) filtering on module and instance basis.
  • Storing and loading logger configuration by using Flash Data Storage.

For API documentation of this module, see Logger module.

Log processing

Logs can be processed using one of the following modes:

In-place processing

When the deferred mode is switched off, the logs are processed in the place where the logger is used. This means that the pointer to a formatted string and the arguments are passed to the logger backend for processing. It is possible for the backend to buffer the logs, but the frontend part of the logging is performed once the backend processing function returns. This approach is straightforward but in many cases not optimal. It can significantly impact performance, especially when logs are used in interrupt context. The operation is not thread-safe and can lead to the corruption of the output.

Deferred processing

In the default deferred mode, whenever the logger is used, the pointer to the string and the arguments are stored in an internal buffer and the log is not processed. It is up to the user to trigger processing whenever suitable. In most cases, the processing is performed in an idle stage, when the system would normally sleep. The size of the buffer can be configured, so that it can be adjusted to the amount of log entries and the nature of idle periods in the application. In the deferred mode, logging takes considerably fewer cycles in the place where it is called (compared to in-place mode), because the processing cost is shifted to idle stage. If the buffer is too small, the logger detects it and injects an overflow marker. In such case, logging is blocked until there is room for new entries in the buffer.

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));
}

A dedicated buffer in the logger is used to store the strings pushed by using NRF_LOG_PUSH. The buffer size is configured through NRF_LOG_STR_PUSH_BUFFER_SIZE. Strings are copied to the buffer without any allocation and deallocation. This means that strings can be overwritten before being processed by the backend. To avoid strings being overwritten, it is recommended to use hexdump (for example, NRF_LOG_HEXDUMP_INFO) instead of NRF_LOG_PUSH.

Logger configuration

The following are the logger frontend configuration options:

  • NRF_LOG_ENABLED - Enable the logger. If disabled, the logger and all logger entries are not compiled.
  • NRF_LOG_DEFAULT_LEVEL - Default severity level. Available options are: ERROR (highest), WARNING, INFO, and DEBUG (lowest). This option configures the lowest severity level that can be present in the system. For example, if it is set to the INFO level, all DEBUG entries are not compiled. Every module can set a local severity level. The actual severity level that is applied for the module is the highest pick from local and global. For example, if the module severity level is set to DEBUG, but the default severity level is set to INFO, then all debug log entries in the module are not compiled.
  • NRF_LOG_USES_TIMESTAMP - If enabled, a timestamp is added to every log entry. The user must provide a function that returns a 32-bit timestamp value during initialization. The source of the timestamp is not important for the logger. If timestamping is enabled and this function is not provided, initialization fails with an error.
  • NRF_LOG_USES_COLORS - If enabled, every string is prefixed with an ANSI escape code with the configured color. The user can configure colors of errors (NRF_LOG_ERROR_COLOR) and warnings (NRF_LOG_WARNING_COLOR) for all modules, and the default color for info and debug logs. Colors for info and debug logs can be overriden by every module.
  • NRF_LOG_DEFERRED - If enabled, the logs are not processed directly where they are called, but deferred to idle state. See Log processing. When NRF_LOG_DEFERRED is enabled, the size of the internal buffer can also be configured (NRF_LOG_BUFSIZE). Standard entries take from 4 to 32 bytes.
  • NRF_LOG_ALLOW_OVERFLOW - If enabled and if the internal circular buffer is full, the oldest entries are removed and new entries are stored.
  • NRF_LOG_FILTERS_ENABLED - If enabled, logs can be compiled as part of a binary file, but not used unless they are enabled (which is especially useful when Command Line Interface is used as a backend).

A module can have a section that overrides its own default logger settings. Modules can override the following configuration:

  • Log activation in the module.
  • Independent lowest severity level.
  • Info log coloring.
  • Debug log coloring.

Usage

Logger usage can be divided into the following tasks:

  • Controlling the logger - initialization, reconfiguration, and triggering processing (in the deferred mode).
  • Logging.

Controlling the logger

The nrf_log_ctrl.h file contains the API for controlling the logger. Before the logger can be used, it must be first initialized:

  • The NRF_LOG_INIT() macro initializes the logger. During initialization, the user must provide a pointer to the timestamp function or NULL if timestamping is disabled. If the deferred mode is used, then it is up to the user to start the processing of the buffered log entries. The NRF_LOG_PROCESS() macro is used for that.
  • When NRF_LOG_PROCESS() is called, the logger attempts to process a single entry and returns true if there are more entries to process, or false if the buffer is empty. When the logger is initialized, it has no backends assigned. The next step is to provide the backend by using the nrf_log_backend_add() call.
  • nrf_log_backend_add() provides the interface to the logger backend. The backend must be already initialized at this point. At any time, a backend can be detached from the logger by using nrf_log_backend_remove(). The logger supports up to 10 backends.

Both the initialization and the addition of common backends are bundled in the nrf_log_default_backends module. The NRF_LOG_DEFAULT_BACKENDS_INIT() macro can be used to initialize and attach RTT or UART backend.

The following code snippet shows how NRF_LOG_PROCESS can be incorporated into the non-preemptive scheduler.

#include "nrf_log_ctrl.h"
#include "nrf_log_default_backends.h"
int main(void)
{
err_code = NRF_LOG_INIT(timestamp_func);
...
while(1)
{
scheduler();
{
//sleep
}
}
}

Use the NRF_LOG_FLUSH() macro to ensure that all logs are processed.

Use the NRF_LOG_FINAL_FLUSH() macro when logs must be flushed in the blocking mode, in case of an error, right before a reset. In such a situation, if you use the NRF_LOG_FLUSH() macro, you do not receive the whole log, as the transmission will be interrupted by the reset.

Logging

The nrf_log.h file contains the API used for logging. There are the following types of log entries:

  • Standard logs with syntax very similar to printf - NRF_LOG_<SEVERITY_LEVEL>().
  • Hexdump - a method for dumping the data - NRF_LOG_HEXDUMP_<SEVERITY_LEVEL>().

The following example shows the simplest way to log data in a module:

#include "nrf_log.h"
void send_func(uint8_t * p_data, uint32_t length)
{
NRF_LOG_INFO("sending data\r\n");
NRF_LOG_DEBUG("%d bytes, data:\r\n", length);
NRF_LOG_HEXDUMP_DEBUG(p_data, length);
if (phy_is_busy())
{
NRF_LOG_ERROR("Phy is busy\r\n");
}
}

Logging customization

You can customize the logging for each module. Modules can override the severity level, the string prefix, as well as the coloring of info and warning logs:

#define NRF_LOG_MODULE_NAME spi
#if SPI_CONFIG_LOG_ENABLED
#define NRF_LOG_LEVEL SPI_CONFIG_LOG_LEVEL
#define NRF_LOG_INFO_COLOR SPI_CONFIG_INFO_COLOR
#define NRF_LOG_DEBUG_COLOR SPI_CONFIG_DEBUG_COLOR
#else //SPI_CONFIG_LOG_ENABLED
#define NRF_LOG_LEVEL 0
#endif //SPI_CONFIG_LOG_ENABLED
#include "nrf_log.h"

If a module consists of several files, the logger customization must be repeated in every file. The only exception is NRF_LOG_MODULE_REGISTER(), which must be called in only one file.

Note
You can also use the following macros to produce cleaner logs, without the default prefix in the user string:

Due to certain limitations, logging a float requires you to use the following dedicated macros:

NRF_LOG_INFO(„float value:” NRF_LOG_FLOAT_MARKER „\r\n”, NRF_LOG_FLOAT(val))

Because customized logging in modules relies on the redefinition of defines, including nrf_log.h in header files can lead to compilation failures.

Filtering logs on instance level

When a module is widely used, filtering on module level is not useful. An extreme example is the module that is used by the logger system. In that case, if a different instance of the module is used elsewhere in the application, logging is impossible unless filtering is applied on instance basis.

The logger provides a set of macros for filtering on instance basis. The approach is similar to filtering on module basis, where for each module a specific set of variables is registered in memory sections (NRF_LOG_MODULE_REGISTER).

Setting up instance level filtering

To use this feature, the instance structure must contain a pointer to the logger structure specific to the instance, and the pointer must be initialized correctly. The logger module provides a set of macros in nrf_log_instance.h. If logs are disabled, the macros are empty and no additional memory is used.

Initialization can be encapsulated into a macro that declares an instance variable (see NRF_BALLOC_DEF).

Declaration of the instance structure:

#include "nrf_log_instance.h"
typedef struct {
...
} foo_t;

Instantiation macro:

#define FOO_DEF(_name) \
NRF_LOG_INSTANCE_REGISTER(foo, _name, ....); \
static foo_t _name = { \
NRF_LOG_INSTANCE_PTR_INIT(p_log, foo, _name) \
... \
}

The NRF_LOG_INSTANCE_REGISTER macro creates a set of variables specific to the instance, such as name, current filtering level, or coloring.

Instance logging

Macros for logging on instance basis are very similar to the standard logging macros with an additional parameter - pointer to the instance.

void foo_init(foo_t * p_foo)
{
//init body
NRF_LOG_INST_INFO(p_foo->p_log, "Init");
}

Log messages specific to the instance are prefixed with <module_name>.<instance_name>, instead of the standard <module_name>.

Performance

In case of deferred logs, timing does not depend on the string length, and only slightly on the number of arguments.

In case of in-place processing with RTT, timing is highly dependent on the number of arguments.

In case of UART, the difference between deferred and in-place logging is even bigger, and highly dependent on the baud rate.

The following table shows performance measurements performed on nRF52.

Number of arguments In-place with RTT Deferred
0 arguments 12 us 3.2 us
6 arguments 300 us 4.0 us

Logger backend interface

Logger backend interface is defined in nrf_log_backend_interface.h. Implementation of the following functions must be provided:

  • nrf_log_backend_api_t::put - this function is called when a log entry is processed by the frontend and it passed the current backend filtering. A message is provided as an argument. The message contains unprocessed data (string pointer and arguments in case of a standard log entry).
  • panic_set - this function is called when nrf_log_panic() is called by the application. On this call, the backend must switch to blocking mode (for example, stop using interrupts) or stop processing new log entries. For details about the logger panic mode, see Panic mode.
  • flush - optional flush.

Messages provided with the nrf_log_backend_api_t::put function are shared between all backends. For this reason, they must be managed by the backend implementation. Memory Object module memory objects are used for storing messages.

When the logger frontend is processing an entry, it allocates memory for the message from the internal pool, removes the entry from the internal circular buffer, and creates the message. Then, it iterates on all attached backends and applies dynamic filtering (if enabled).

When the backend gets the message, it must indicate that it is in use by calling nrf_memobj_get. This ensures that the message is not freed.

nrf_memobj_put must be called when backend finished processing the message. The message is returned to the memory pool if it is processed by all backends.

Warning
In the current implementation, each and every logger backend must run on lower or equal priority as the module that is writing logs.

Flash logger backend

The flash logger backend is used to store logs in non-volatile memory.

The backend consists of the following logical parts:

  • flashlog - used to store log entries during application lifetime,
  • crashlog - used to dump messages logged before an error condition (NRF_LOG_FINAL_FLUSH) and between NRF_LOG_FINAL_FLUSH and reset.

From the logger perspective, these parts are seen as independent logger backends. However, internally they share the same scheme of storing and reading log entries.

Flash operations

The module uses dedicated flash pages that are configured in SDK configuration header file. Exact pages can be specified, or pages following the application code can be used (NRF_LOG_BACKEND_FLASH_START_PAGE set to 0). The module uses Flash storage (fstorage) to store the logs.

The flashlog uses the Flash storage (fstorage) asynchronous API provided during intialization, while the crashlog reinitializes Flash storage (fstorage) to work in a direct, synchronous way.

Log entries are serialized and stored in a dedicated area one by one until there is no more space for them. Logs are dropped if there is no space available and the area must be explicitly erased by using nrf_log_backend_flash_erase or a CLI command. On initialization, the flash area is scanned to find the last entry and the following entries are stored after it.

Note
Strings that are used as an argument to the log message and are stored in RAM (for example, when NRF_LOG_PUSH is used) will be corrupted, since only the address of the string is stored.

Flashlog operations

Once the flashlog backend is initialized and enabled, it receives log messages that match the filtering configured for this backend. Flashlog attempts to write messages to flash by using asynchronous Flash storage (fstorage) API. Since access to flash is time-consuming and the area is limited, improper logger filtering configuration can lead to system overload. It is recommended to store only warning and error messages. When flashlog is used, it is recommended to increase NRF_LOG_MSGPOOL_ELEMENT_COUNT. This is related to the fact that flashlog keeps a log message until it is written to flash.

Crashlog operations

In a standard operation, the crashlog keeps a FIFO of the most recent log entries that match the filtering. Whenever a new log message is put into the FIFO, the oldest one is freed. Crashlog does not perform any flash operation until panic occurs (NRF_LOG_FINAL_FLUSH). When panic occurs, Flash storage (fstorage) is reconfigured to synchronous mode and all logs from the FIFO are written to flash memory. Any log messages received in panic mode are directly written to flash. When crashlog is used, NRF_LOG_MSGPOOL_ELEMENT_COUNT must be increased at least by NRF_LOG_BACKEND_CRASHLOG_FIFO_SIZE, compared to the default value.

Command Line Interface support

The flash logger backend module provides CLI commands (NRF_LOG_BACKEND_FLASH_CLI_CMDS) for getting the status, reading, and clearing flashlog.

Panic mode

When the system enters an unrecoverable error stage, it can no longer use interrupts and it is vital to retrieve the full log. The NRF_LOG_FINAL_FLUSH() sends a panic notification to all attached backends through nrf_log_panic() call. When logger system switches to panic mode, the log messages are flushed. The logs that follow are processed in a blocking manner.

Command Line Interface

Logger has a set of built-in Command Line Interface commands that are enabled with NRF_LOG_CLI_CMDS option. Commands can be used to control logger features and get logger status.

The following table lists the supported commands.

Command name Description Command syntax
status Prints the current severity level configuration for all modules and module instances present in the system. -
list_backends Prints all backends compiled in the system with the current status and ID. -
halt Suspends logging in the system. -
go Resumes logging in the system. -
enable Enables logging the messages for the current instance of Command Line Interface as a logger backend, up to the provided severity level in the listed modules. Multiple modules can be enabled in a single command. log enable <level> <module_A> <module_B>

Example: log enable debug app_timer* queue.my_queue hardfault
disable Disables logging the messages for the current instance of Command Line Interface as a logger backend, in all modules or in the listed ones. log disable <optional_module_A> <optional_module_B>
config Loads or stores dynamic configuration of the logger in the fds record. The configuration includes dynamic settings for all backends present in the system. log config store, log config load
backend Enables control for another backend present in the system. A typical use case for this command is to configure the logger for Flash logger backend backend followed by log config store to ensure that configuration is persistent. log backend <backend_name> <any_other_log_command>

Example: log backend flash_log_backend enable warning my_module