If you haven't yet get to know command line interface (nrf_cli) module significantly improved in nRF5 SDK 14.0.0 please check this blog post: New command line interface - part 1
Enhanced logger and console
It seems like a natural fit to use the console as a way of presenting logs to the user, as well as configuring which logs should be printed, to avoid flooding the console with logs. There are other natural fits for the logger, like storing logs to non-volatile memory, so logger could not be tightly coupled with the console. On the other hand, it had to support simultaneous cooperation with multiple client backends. Additionally, each backend wants to get different logs (e.g. because backends have different capacity). In nRF5 SDK v14.0.0, the logger has been significantly improved to support such cases in a generic way. The main changes and new features are:
- Simple interface to logger backend.
- Support for multiple backends.
- Backends can be added and removed at runtime.
- 2 levels of filtering: compile time (sdk_config.h) and runtime. Runtime filtering is independent for each backend.
- Log entry is stored in an internal circular buffer only if there is any backend which is waiting for that log. Otherwise, log entry is single condition checking.
Logger commands
The console (nrf_cli) implements the same logger backend interface as other backends, but since it is a two-way user interface, it opens up new options, as the users can now interact with the logger module (as easily as they can interact with any other module). Users can enable and disable logs globally and on individual module basis. Since the logger supports multiple simultaneous backends and because nrf_cli can have instances, you can use two consoles at once (e.g. UART and BLE UART) and display different logs.
To start using the console as a logger backend, you need to simply add console to the logger (see example peripheral/cli or ble_peripheral/experimental/ble_app_cli) and configure nrf_cli (enable nrf_log backend feature - NRF_CLI_LOG_BACKEND flag) and nrf_log properly (enable filtering - NRF_LOG_FILTERS_ENABLED flag). You must also enable logging, both globally (and set the maximum allowed level in the application - NRF_LOG_DEFAULT_LEVEL) and in the modules in which you would like to log (since nRF5 SDK 14.0.0, you will find this option in nrf_log section of sdk_config.h). When the backend is added to nrf_log, you can also set the default severity level for each module for that backend. If you expect to have many logs, then the backend can be started with all logs off (NRF_LOG_SEVERITY_NONE).
Once you start your application, you can control the logger settings using the log command. The following subcommands are supported:
Logs sent to the console are multiplexed with the command output so if there is a lot of logs printed in the system, it is useful to suspend them for a moment before command execution (log halt). They can be later resumed (log go). 'Log disable' disables all logs for good. You can always check the status of logs using the log status command.
Enabling logs for each module is super easy, thanks to the auto-completion feature of nrf_cli. You can use the Tab key to print the available options. A specific logging level can be set for multiple modules: log enable info app uart spi.
Below is an example of enabling logs in the UART driver when UART is used as transport for nrf_cli. The console is flooded with logs (it is still usable) and many logs are lost. Additionally, in the example, timestamping and colors were enabled in the logger and custom coloring was set in the UART driver.
UART logs configuration:
Adding logs to a new module
A new module can start using the logger immediately. The simplest way is to include "nrf_log.h" and start using logger macros. If no new module is defined, logs will be 'assigned' to the 'app' module. If you want to have an independent module with a specific prefix and ability to filter it, you need to specify the name and register the module:
#define NRF_LOG_MODULE_NAME my_module
#include "nrf_log.h"
NRF_LOG_MODULE_REGISTER();
Note that if 'my_module' consists of more than one C file, then the registration macro must be present in only one file.
After those 3 lines are added, after recompilation, the logger will 'see' the new module. However, the module can be further customized with:
- Individual compile time filter (otherwise NRF_LOG_DEFAULT_LEVEL is used)
- Individual info and debug color (otherwise, the default color is used)
Fully customized log configuration:
#define NRF_LOG_MODULE_NAME my_module
#if MY_MODULE_CONFIG_LOG_ENABLED
#define NRF_LOG_LEVEL MY_MODULE_CONFIG_LOG_LEVEL
#define NRF_LOG_INFO_COLOR MY_MODULE_CONFIG_INFO_COLOR
#define NRF_LOG_DEBUG_COLOR MY_MODULE _CONFIG_DEBUG_COLOR
#else // MY_MODULE _CONFIG_LOG_ENABLED
#define NRF_LOG_LEVEL 0
#endif // MY_MODULE _CONFIG_LOG_ENABLED
#include "nrf_log.h"
NRF_LOG_MODULE_REGISTER();
Houston, we have a problem - panic mode
In case of critical error in the system, we want to flush all logs. However, in such situation we cannot rely on our system (interrupts, task switching). It implies that the mode of logger operation (especially backends) needs to change to blocking mode. The logger backend interface includes a call which informs a backend that since now panic mode should be used. It is up to the backend to react properly. In case of UART, it will be reconfiguration to blocking mode, but in case of nrf_cli using BLE UART, switching to panic mode means shutting down the backend because BLE UART requires the SoftDevice and thus requires interrupts.
Adding a new backend
A logger backend has to implement a very simple interface. It consists of the following functions: put_message, panic_mode_set, flush (not used in current version of nrf_log). A message consists of a single log entry details (pointer to a string, arguments, timestamp, severity, etc.).
Memory for a message is allocated from an internal logger pool and pointer to that message is sent to all backends that passed filtering. This approach minimizes RAM usage since it does not depend on the number of currently active backends, but it requires that a backend indicates when message is no longer needed and can be freed. Memory is freed when the last backend 'frees' the message. nrf_memobj API is used for that (nrf_memobj_get()/nrf_memobj_put()).
With this approach, it is up to backend implementation when a message will be processed. However, the backend must be responsible since holding too many messages may lead to a situation where there is no memory in the pool, new logs cannot be processed, and logger will start dropping log entries. It is recommended that if the backend cannot process all messages on time, it should start dropping them. An example of such approach can be seen in nrf_cli logger backend implementation. nrf_cli has an internal queue of pointers to logger messages and if this queue gets full, then the oldest logger messages are dropped.
Under the hood – log processing path
The logger was designed with two main goals in mind: thread safety and efficient and fast logging. In order to achieve that, logging has to be split into stages (so called deferred mode).
In the first stage, in the context where log entry occurs, data (pointer to the string, arguments, timestamp) is stored in the circular buffer (thread safe operation). The second stage is triggered by calling NRF_LOG_PROCESS() or NRF_LOG_FLUSH() macro. It is up to the application to pick the right time for processing. It is recommended that processing is triggered in idle state. In the processing stage, a message with a single log entry is sent to all backends (after filtering). The user has to keep in mind that in case of more complex logger backends, backend processing may not occur in the context of NRF_LOG_PROCESS() call and additional trigger may be needed ( e.g. nrf_cli).
Summary
NRF5 SDK v14.0.0 contains an improved nrf_log. It has been extended to support multiple backends and dynamic filtering of logs based on module and severity level. Backends are decoupled from the logger and nrf_cli instance can act as a logger backend for presenting the logs, but also to control them. NRF5 SDK v14.0.0 has two examples which showcase nrf_cli and logger integration (peripheral/cli and ble_peripheral/experimental/ble_app_cli).
