Logging Subsystem Enhancements

[nashif]

• Modify namespace (SYS_LOG -> LOG)
• Support multiple backends
  • FCB
  • memory
  • filesystem
  • networking
  • mcumgr(!)
• Add timestamps
• Provide meta-data (such as log level) separately to the backend (right now it's embedded into the pre-formatted string)
• multi-core support: master - slave configuration where one core acts as slave and the master collects logging from the slave and displays the logs of the system as a whole

[carlescufi]

@ccollins476ad FYI, for 1.12

[nashif]

[carlescufi]

CC @pizi-nordic

[galak]

As part of this cleanup can we look at supporting an API that allows the user to do something like:

LOG(level, log_format, ...)

and have features like COLOR work consistently.

[pizi-nordic]

I would like to present a logger design which I think might be suitable for the Zephyr. I will post my proposal in parts, starting from the high-level overview. It will be later followed by some notes about the implementation and advanced features like multi-core support and Trust Zone integration.

Introduction

The complexity of modern embedded systems enforces changes in our working methodology. Challenges we face every day include:

• Large amount of data.
  The continuously increasing speed of peripherals is a dominating factor that influences rate of debugging data generation, while complexity of the protocols, peripherals and firmware determines size of generated data as more information is needed to describe state of the monitored component and the system. The amount of data generated during testing and debug sessions negatively impact on the data analysis time. As result, we can observe creation of dedicated tools, which are verifying system behaviour basing on the received data, extract required information from data stream or convert the information into a form which is easier to analyse by human.

• Existence of multiple separated domains in the system.
  This includes multi core and multi CPU systems as well as new technologies like Trust Zone. Usually in such case firmware for each domain is being developed separately, however system behaviour and performance depends on successful cooperation of all components. As result the tools we need must be able to present system-level view of the firmware internals in order to easily trace interaction between domains. The detail view is also needed as complex systems are built from large number of components. Developer must be able to focus on currently developed or tested module and silence all noise coming from other parts of the system.

These challenges faced every day by a developer, tester or system integrator could be addressed by dedicated logger subsystem, presented in this document.

Requirements

The core requirements of the logger are defined by its usability:

• Performance.
  The performance is the key parameter of the logger subsystem. As the logger acts as observer of the system internals it has to have minimal impact on the observed entities. Minimizing time needed to log data is especially important in real-time subsystems, which just fails if deadlines are not met. The log processing and transmission speed is also important, as there could be a lot of log data which have to be gathered in order trace down complex problem.

• Context-free operation and lock-less log gathering.
  The data logging function must neither take any locks nor wait for any other kind of resources. Moreover, it should be prepared to be interrupted at any time by higher priority code, which could also use the same API for logging.

• Support for multiple log levels and component/instance separation.
  Depending on the situation, the system-level or detailed view is needed. The good logger to support different log levels for different components on the system in order to minimize amount of information not relevant to the currently performed task. This is especially important for modules which are re-used in multiple places of the system. For example, the pool-based memory allocator must have different log level setting for each pool, as enabling full debug component-wise might generate overwhelming amount of information.

• Ease of use.
  The logger usability is also defined by the amount and quality of the presented information. The easier it will be to use, the more likely developer will put it in the newly created code and the more information will be available. Moreover, access to the data and integration with both internal (for example memory management subsystem or building infrastructure) and external infrastructure (like custom testing frameworks) should be as simple and straightforward as possible. The human factor cannot be underestimated while thinking about logger usage - simple features like colours might be used to catch attention to the most important messages significantly reducing time need for log analysis.

Operation Principles

Logger Frontend

The Logger Frontend collects logs form the system. From the developer perspective it mimics printf() interface. Dedicated macro (one for each log level) accepts format string and optional arguments:

LOG_ERROR("This is error");
LOG_WARNING("This is warning with %u argument", 1)
LOG_INFO("This is info message with %u %s", 2, "arguments");
LOG_DEBUG("This is debug message");

The most important difference between the printf()-based solutions and the proposed logger is the processing of data. The macros presented above do not perform any processing. Instead they just store the pointer to the format string and optional arguments in the dedicated buffer. As result the cost of message logging is equal to few memory writes. The stored data in converted to to the human-readable string later, in the idle loop of the system in order to avoid negative impact of increased CPU load on the system operation. The proposed behaviour has one limitation, which must be taken under consideration by every developer using the logger: as processing is performed in the idle loop, some time after macro execution, thus all string pointers provided to the log system have to be valid all the time.

In addition to the data provided by developer, the macros automatically add some metadata, like timestamps, identifier of module generating logs as well as log level. All the information is stored into a buffer (the circular buffer is an obvious choice, however it has some drawbacks which will be discussed later) where it waits for the further processing.

Logger Core

The Logger Core is responsible for management of log processing. As the log processing must have minimal impact on the system, the Logger Core is called directly from the idle thread and can be pre-empted any time. Moreover, to minimize latency in systems when no preemption is used, it processes single log message on each call, allowing system to check if there is a more important task to handle as often as possible. On each call, single log entry is fetched from the buffer in which it was stored by the frontend and is passed to connected backends.

Logger Backend

The backend is responsible for log messages presentation, transmission or storage. Usually, at the first stage of processing, backend converts the data received from logger core into a human-readable from: the printf()-like expression is evaluated and converted to string, which is prepended by metadata and terminated by end of line string. Additional presentation tasks, like for example applying colours to warning and error messages, are also performed at this stage. Then, the generated strings are sent to the host:

[00:01:24.548072] <error> example_module: This is error
[00:01:24.548073] <warning> example_module: This is warning with 1 argument
[00:01:24.548074] <info> example_module: This is message with 2 arguments
[00:01:24.548075] <debug> example_module: This is debug message

The backend could also perform any other action on the received logs. This include storing them in flash or forwarding them to host without rendering.

Basic Features

Log Filtering

The log filtering is done separately for each backend basing on log level and source of the message (module/instance id). Such approach allows for debugging one backend using another one as well as forwarding selected messages (like errors and warnings) to dedicated backend (for example a flash-based storage).

The log filtering is done in 2 places in order to minimize amount of CPU time needed to collect and process logs. The coarse check is done in the Logger Frontend: the LOG_* macros does not perform any action if there is no backend waiting for a messages of given level from given module. If the message pass this check, the Logger Core do the final filtering by routing the messages only to backends requesting the such information.

Object Dumping

The delayed processing of the log messages might be a problem when a developer would like to log some strings (in general: any data) which is only available at the time of LOG_* macro execution. To address this problem, an object dumping interface is provided. The developer might use dedicated macro (LOG_HEXDUMP()) to insert blob of data into log buffer. Such blob is then presented to the user as a hexdump of stored data. Unfortunately this feature has an significant cost, as the log buffer must be large enough to hold whole dumped object.

Similar mechanism might be used as a compatibility layer in order to provide equivalent of the existing printk() interface.

Panic Mode

As proposed logger buffers the messages, an implicit flush is required when unrecoverable errors is detected. Also, some backends (for example a network based ones) usually are not able to work properly after critical error . In order to allow logging during faults, a panic mode is introduced. When Logger is informed about system fault it:

• Informs backends that system is in panic mode.
  The complex backeds relaying on large subsystems (like network stacks), should immediately stop to avoid further errors. Simpler backends should minimize their dependence on the system components and switch to blocking mode. For example, the UART backend should use polling instead of interrupts and send every message as soon as possible without any additional buffering. Moreover, the backends could change its filtering settings in order to output as much information as possible.
• Flushes log buffer.
  This step forces rendering of all stored logs and its transmission in blocking mode.
• Become blocking.
  When log buffer is empty, the logger system become blocking. The LOG_* macros directly calls backends as there is no hope that the system will return to the idle thread to process logs there.

[jhedberg]

Would you consider trying to shorten the API names a bit? E.g. LOG_WARN, LOG_INFO, LOG_ERR and LOG_DBG? Part of the parameter list is often a fairly long string, and having to split it up something to be avoided.

[pizi-nordic]

@jhedberg: Good idea!

[skordal]

I think it would be nice if Zephyr could also provide macros that mimic the vprintf() functionality (by taking a va_list parameter). It would make it easier to use Zephyr as logging backend for other projects, such as libmetal, where we need to forward the formatting arguments from another function (see OpenAMP/libmetal#38).