RFC[1/2] Common logging infrastructure and API


Saucedo Tejada, Genaro <genaro.saucedo.tejada@...>
 

Hello, please review this proposal and provide feedback if possible.
This email should be followed by a patch containing a prototype
implementation for reference but not meant to be applied.

Background:
 
Currently several files declare their own logging infrastructure and
sometimes even in the same way, effectively duplicating code, there is
no common logger header or a single interface for logging, this
situation also complicates enhancement of logging functionality.

We want to concentrate logging functionality at a single point to ease
configuration and enhancement while retaining (and reusing) all
existing logging features when decided by developers.

Additional features are proposed anticipating possibly desired
functionality.

Proposal to implement new logging API:

Create a new header file at include directory, remove all logger macro
definition from .c files and have a single, compatible definition on
the new header. On each .c file that requires logging include the new
header and specify feature/file specific values, such as logging domain
(if any) and per-feature logging switch (view number 2.1 below).

The retained features surveyed on existing implementations of logging
are:

1. Make based identification of output appender, these currently being
stdio printf when console is available and printk as fall back.

2. Optional macro expansion, controlled by Kconfig files and make
menuconfig command. Disabling this helps saving memory on production
when logging is not needed.

2.1. Fine grain per-feature log activation. Allows enabling log at
specific parts of the code on menuconfig.

3. Multilevel log formatting.

3.1 Colored log, when console is active it helps differentiate three
existing log levels. currently in use only on Bluetooth files.

4. Caller thread printing, currently Bluetooth files print the current
thread pointer.

5. Caller function printing, some logging macros print the function
that called them.

All above features are kept by this proposal and most become
configurable. The following new ones are added:

6. Labeled log, helps differentiate log levels by using a tag, useful
if color is not available.

7. Incremental per-level log activation. Orthogonal to existing per-
feature filter, this filter allows to set one logging level out of:
INFO, ERROR, WARNING and DEBUG. The higher the level the more verbose
the log becomes. Also as levels are hidden by preprocessor decreasing
level also helps reducing footprint. This is set at menuconfig as well.

Design decisions and rationale:

It was decided to implement this API preferring macros instead of run-
time functions (except for thread retrieval) in an attempt to minimize
overhead introduced by logging.

Also, within this macro implementation, two extreme sides can be
discerned, these are concatenate compile time values with preprocessor
## versus using printf format arguments (%s). Preferring formatting
slightly impacts run-time overhead while preferring preprocessor
concatenation produces longer strings that duplicate substrings. In
this case none of the extremes was reached, instead something closer to
formatting was picked seeking to keep the prototype code simpler. Final
patch can be tuned likewise or one of the two extreme approaches can be
taken.

Implementation details:

The patch following this email is meant as proof-of-concept prototype.
It might compile but has not been thoughtfully tested and it only
covers Bluetooth and lcd_rgb.c files.

In this example path configuration is done through menuconfig, new
options need to be enabled in addition to existing ones, for modified
files CONFIG_BLUETOOTH_CONN, CONFIG_BLUETOOTH_DEBUG,
CONFIG_BLUETOOTH_DEBUG_HCI_CORE and CONFIG_GROVE_DEBUG.

A "logging domain" can be specified, it helps filter a log output in
case several features are enabled, domain is specified by:
LOG_DMN: short for log domain.

Example:
#define LOG_DMN "bt"

The macros at logging.h get enabled by two definitions:
CONFIG_USE_COMPILE_LOG: This is the global Kconfig switch for logging.
LOG_THIS_MODULE: This is an additional switch intended to bridge the
generic definitions on the header to a feature-specific logging switch
from Kconfig.

Example usage of LOG_THIS_MODULE:
#define LOG_THIS_MODULE CONFIG_BLUETOOTH_DEBUG_HCI_CORE
#include <logging.h>

That way logging.h will know that if CONFIG_BLUETOOTH_DEBUG_HCI_CORE
was not set by menuconfig it should not log at all (at current
compilation unit).

This requires an additional line to be included by files that use
logging but could be made optional, doing so requires deciding default
behavior between having unfiltered features (on 2.1 filter mentioned
above) or allowing developer to included logging.h file with no effect.
On current prototype this line requirement is enforced by #error
directive.

Future work:

* Final patch needs to unify system wide the macro naming and such
naming should be less likely to collide.
* An alternative run-time implementation could be later developed to
provide more features.
* Compare footprint between different degrees of ## usage over printf
format.

Example macro expansions:

printf("" "%s%s\t%p: %s" "Grove LCD: background set to white\n" "%s\n",
"DBG ", __func__, sys_thread_self_get(), "", "");
(messages were left unchaged so domain is still repeated as part of the
message)
printf("bt" ":\t" "%s%s\t%p: %s" "Unable to allocate new HCI command"
"%s\n", "", __func__, sys_thread_self_get(), "\x1B[0;31m", "\x1B[0m");
(domain is defined through macro, color and thread are in use)
printf("bt" ":\t" "%s%s\t: %s" "No HCI driver registered" "%s\n", "",
__func__, "\x1B[0;31m", "\x1B[0m");
(same but without thread)

Join devel@lists.zephyrproject.org to automatically receive all group messages.