nRF5 SDK v15.3.0
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:

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:

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:

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

Usage

Logger usage can be divided into the following tasks:

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:

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:

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:

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:

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

Documentation feedback | Developer Zone | Subscribe | Updated