The logger module provides logging capability for your application. It is used by SDK modules and can be also utilized in 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.
- Optional timestamping.
- Optional coloring of the logs for different modules and different severity levels.
- Prefixing log entries with the module name.
- Optional deferring of log processing to idle stage.
- Logging mechanism decoupled from the logger backend.
- RTT and UART as logger backend.
- Easy path to add customized backend, such as flash storage.
Logs processing
Logs can be processed in two ways:
- In-place processing.
- Deferred processing.
If the deferred mode is switched off, the logs are processed in the place where the logger is used. It 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.
In the 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:
- When passing a pointer, the compiler will give a warning and the argument must be 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 a variable 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.
For example, the following way of logging a temporary string is not recommended:
void foo(void)
{
char string_on_stack[] = "stack";
}
Instead, use the following way of logging a temporary string:
void foo(void)
{
char string_on_stack[] = "stack";
}
Configuration
The logger configuration consists of two parts:
- Configuration of the logger frontend (or just the logger).
- Configuration of available logger backends.
The following are the logger frontend options:
- NRF_LOG_ENABLED - Enable the logger. If disabled, then 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 and 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, then 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, then 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, then the logs are not processed directly where they are called but deferred to idle state. See Logs processing. When NRF_LOG_DEFERRED is enabled, the size of the internal buffer can also be configured. The size is provided in 32-bit words. Standard entries take from one to eight words.
The following are the logger backend options:
- NRF_LOG_BACKEND_MAX_STRING_LENGTH - Maximum length of the string after formatting.
- NRF_LOG_TIMESTAMP_DIGITS - Number of digits to represent the timestamp value. 32-bit value fits in 10 digits but it can be reduced if it is not expected that timestamp value will need full range.
- NRF_LOG_BACKEND_SERIAL_USES_UART - Enables UART as a medium for printing out logs. Additionally, UART pins, flow control, and baud rate can be configured.
- NRF_LOG_BACKEND_SERIAL_USES_RTT - Enables RTT Viewer as a medium for printing out logs. Both UART and RTT can be enabled at the same time.
- NRF_LOG_GETCHAR() - A blocking macro that returns the received byte. Applicable when RTT or UART are used for logging but you need this communication channel for loading data from the host, as in some of the examples.
A module can have a section that overrides default logger settings for the given module. Modules can override the following configuration:
- Enabling logs in the module.
- Independent lowest severity level.
- Info logs coloring.
- Debug logs coloring.
Usage
Logger usage can be divided into two 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 and the default backend. 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 processing of the buffered log entries. The NRF_LOG_PROCESS() macro is used for that. When NRF_LOG_PROCESS() is called, then 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.
The following code snippet presents how NRF_LOG_PROCESS can be incorporated into the non-preemptive scheduler.
#include "nrf_log_ctrl.h"
int main(void)
{
...
while(1)
{
scheduler();
{
}
}
}
Use the NRF_LOG_FLUSH() macro to ensure that all logs have been processed.
Use the NRF_LOG_FINAL_FLUSH() macro to reinitialize the backend to the blocking mode and wait for all data to be sent to the host. Use this macro in case of an error, right before a reset. In such a situation, if you use the NRF_LOG_FLUSH() macro, you will not receive the whole log, as the transmission will be interrupted by the reset.
In certain cases (e.g. error handler), it might be required to change the behavior of the backend (e.g. no context changing). At any point in time, the NRF_LOG_HANDLERS_SET() macro can be used to provide new backend functions for handling log entries.
Logging
The nrf_log.h file contains the API used for logging. There are two 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 is an example of the simplest way to log data in a module:
#include "nrf_log.h"
void send_func(uint8_t * p_data, uint32_t length)
{
if (phy_is_busy())
{
}
}
You can customize the logging for each module. Some configuration defines can be redefined before the header is included. 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"
Note: You can also use the following two 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:
Because customized logging in modules relies on the redefinition of defines , including "nrf_log.h" in header files might lead to compilation failures.
Performance
The following measurements were performed on nRF52. In case of deferred logs, timing does not depend on 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.
Number of arguments | In-place with RTT | Deferred |
0 arguments | 12 us | 2.5 us |
6 arguments | 300 us | 4.0 us |
Customizing the logger backend
You can add another implementation of the logger backend. The logger frontend uses two function pointers from the backend to forward the entry processing to the backend:
- Function for processing standard entries - Function returns true is the entry was processed or false if not (for example, when the backend was busy).
- Function for processing hexdump entries - Function returns information about how many bytes the backend has processed. The logger frontend will take that into account when triggering the logger backend again.
It might be also important to provide a different implementation for outputing logs from an error condition when the system is limited, such as when the context cannot switch, or when the SoftDevice cannot be used. The NRF_LOG_HANDLERS_SET macro can be used to change handlers on the fly.