This is the second attempt to define a common system logging API,
Original thread can be seen here:

https://lists.zephyrproject.org/archives/list/devel(a)lists.zephyrproject
.org/thread/A6CROK67VKFKFSCENJ6UVQL2IRNHLNW2/#A6CROK67VKFKFSCENJ6UVQL2I
RNHLNW2

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 reusing some existing logging
features.

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, 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 7 below).

The surveyed features selected for this logging API are:

1. Kconfig based selection of output backend, these currently being
stdio printf when console is available and printk as fall back.

2. Optional macro expansion, controlled at compile time by Kconfig
files and make menuconfig command. Disabling this helps saving size at
binary images when logging is not needed.

3. Multi category logging, this allows to only enable some of the
logging macros. Previous proposal considered "levels" that are
inherently incremental, i.e., a given level is always a super set of
lower levels. New proposal doesn't force precedence between any of the
four defined macros.

4. Caller thread printing, optionally prints the current thread
pointer.

5. Caller function printing.

New features are added:

6. Labeled log, helps differentiate log categories by using a label at
the beginning.

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

8. Logging domain, a string optionally specified to be appended to log
messages in order to helps differentiate log output in case several
features are enabled, domain is specified by definition of
SYS_LOG_DOMAIN macro.

Design decisions and rationale:

This API was implemented based on macros instead of run-time functions
(except for thread retrieval) in an attempt to minimize both execution
overhead and binary size increments introduced by logging.

It's important to emphasize that by leaving log activation logic to
preprocessor (at compile time) the binary images size can be
effectively reduced by decreasing the amount of activated log macros,
of course verbosity is reduced as well.

The macros also act as a facade that can be implemented in the
background by different implementations, currently printk and printf
are the only available implementations.

Taking into account feedback from previous RFC version, specifically ht
tps://lists.zephyrproject.org/archives/list/devel(a)lists.zephyrproject.o
rg/message/RKVXWR75XFN3TCXKQV2STRACPMPVSEB4/, a given log macro gets
activated when its category is selected for the current module. Such
combination allows to specify different verbosity at each module.

The macro categories are intended to filter the log according to the
nature of the messages, e.g., ERROR category would report failures
found by the program during execution while DEBUG could record tracing
information relevant to programmer during development and debugging.

Each module needs its own category specified and different modules
might have different categories specified. For example, a new driver
might depend on GPIO, so for debugging this new driver the GPIO related
module gets its log category set to ERROR and the driver has all
categories activated, that way developer can identify when an error was
 encountered by GPIO code, without having to see messages on all the
categories at GPIO code, and could check the DEBUG category of the new
driver to see the details on how was this error handled.

Implementation details:

The macros are defined at include/misc/sys_log.h, they get enabled by
the per-module switch SYS_LOG_LEVEL (specified before header include)
and the global switch (CONFIG_SYS_LOG).
The per-module switch gets relayed at .c file from the Kconfig options
in the following way:
#define SYS_LOG_LEVEL CONFIG_SYS_LOG_GROVE_LEVEL
#include <misc/sys_log.h>

If SYS_LOG_LEVEL is not defined a default is
used: CONFIG_SYS_LOG_DEFAULT_LEVEL. Previous approach was to enforce
the definition by failing compilation if not defined.

The following switches control some optional formatting:

CONFIG_SYS_LOG_ENABLE_PRINTF: specifies printf as backend.
CONFIG_SYS_LOG_ENABLE_PRINTK: specifies printk as backend.
CONFIG_SYS_LOG_SHOW_TAGS: sets category tags on.
SYS_LOG_DOMAIN: sets domain string that will be included at the start
of the messages.
CONFIG_SYS_LOG_THREAD: specifies whether to print thread pointer or
not.

Log categories are selected through a bitmap, each of the 4 least
significant bits of bitmap correspond each of the four defined
categories. Macros get activated when the bit for their category is 1
on the SYS_LOG_LEVEL of including compile unit, e.g.:

When SYS_LOG_LEVEL is 9 (0b1001) for current compile unit SYS_LOG_DBG
and SYS_LOG_ERR, corresponding to ERROR and DEBUG categories, are
active. The macros SYS_LOG_INF and SYS_LOG_WRN instead expand to "{ ;
}"

0b0000 //LOG is off (0)
0b1000 //LOG is ERROR (1)
0b1100 //LOG is ERROR + WARNING (3)
0b1110 //LOG is ERROR + WARNING + INFO (7)
0b1111 //LOG is ERROR + WARNING + INFO + DEBUG (15)

Future work:
Subsequent patches need to define a sanity test, and replace old DBG
macro calls on several files.

Hi Genaro,

Could you give the gerrit links?

The following switches control some optional formatting:

CONFIG_SYS_LOG_ENABLE_PRINTF: specifies printf as backend.
CONFIG_SYS_LOG_ENABLE_PRINTK: specifies printk as backend.

Aren't these 2 being mitigated by CONFIG_STDOUT_CONSOLE ?
If this option is set: printf will be used, printk otherwise.

Tomasz

On Fri, 2016-03-11 at 11:49 +0100, Tomasz Bursztyka wrote:

Hi Genaro,

Could you give the gerrit links?

The following switches control some optional formatting:

CONFIG_SYS_LOG_ENABLE_PRINTF: specifies printf as backend.
CONFIG_SYS_LOG_ENABLE_PRINTK: specifies printk as backend.

Aren't these 2 being mitigated by CONFIG_STDOUT_CONSOLE ?
If this option is set: printf will be used, printk otherwise.

Tomasz

Yes, I got a similar comment on gerrit, this has been done in such way
because in the future more "back ends" are expected, i.e., other
functions could be called hence a "back end" menu choice. But for
following patch I'm likely removing that.

Somehow outdated patches are available at gerrit:
https://gerrit.zephyrproject.org/r/691
https://gerrit.zephyrproject.org/r/722

CONFIG_SYS_LOG_ENABLE_PRINTF: specifies printf as backend.
CONFIG_SYS_LOG_ENABLE_PRINTK: specifies printk as backend.

I really think that officially supporting both printk() and printf() in the kernel is a bad idea. Having Zephyr depend on libc APIs really isn't the way to go. Zephyr should not care whether printf() exists or not.

The real "backend" should simply be the character output routine, an interface for emitting one character to an output device, whether a RAM buffer, IPM channel, UART, etc. Currently this is managed by ad hoc private APIs, but this would be a good thing to make official.

Andrew