On Wed, 2016-03-02 at 11:08 -0500, Benjamin Walsh wrote:

FYI, in thunderdome we have also created a log system solving some
of
the problems you mention in your RFC. Here are my 2 cents following
our experience:

 - In our implementation we now support only a global log level
(INFO,
 WARNING, ERROR) + a special DEBUG level which is activated at
compile
 time for each module separately. Originally we also had a log
level
 per module but it quickly proved to be mostly unused by the users,
 while adding some complexity (conflicts between global log levels
and
 per module log level), so we removed it, also to save space.

Maybe it did not come clear in my reply, but what I proposed did not
have a global logging level, or rather, the global level is always
"OFF". Each subsystem that you want to log has to enable it, with
their
own level. I think that would give a good control on the verbosity.

Regards,
Ben

This could be implemented without a "global" category but providing an
menu option to rise log level of every category lower than user input.

Currently I have a "default" log level to deal with modules use log but
don't define a module switch, it's not clear yet whether logging.h
should enforce specification of module switch or not.

FYI, in thunderdome we have also created a log system solving some of
the problems you mention in your RFC. Here are my 2 cents following
our experience:

- In our implementation we now support only a global log level (INFO,
WARNING, ERROR) + a special DEBUG level which is activated at compile
time for each module separately. Originally we also had a log level
per module but it quickly proved to be mostly unused by the users,
while adding some complexity (conflicts between global log levels and
per module log level), so we removed it, also to save space.

Maybe it did not come clear in my reply, but what I proposed did not
have a global logging level, or rather, the global level is always
"OFF". Each subsystem that you want to log has to enable it, with their
own level. I think that would give a good control on the verbosity.

Regards,
Ben

On Mon, 2016-02-29 at 12:48 -0500, Benjamin Walsh wrote:

We need to make sure we support logging for more than debugging
and
during development. In most cases logging will be used during
development
to assist with debugging and printing information on the console,
however,
we need to make sure this design also addresses cases where
logging is part
of the application, for example you might want to write to a
file-system, send
messages to a remote endpoint or write messages to a connected
display.
This basically means we also need to support different backends,
the most
immediate and straightforward backend would be printing to the
console
using printk and printf.

An application should be able to configure the domains and levels
it wants to
log, for example, if I am debugging an issue with I2C and I am
only interested
in I2C, I want to be able to select this domain and the logging
level, so for
example:

the defaults:
CONFIG_LOG=y
CONFIG_LOG_BACKEND=“printk”

Implementing this.

CONFIG_LOG_DOMAINS=“*”

CONFIG_LOG_LEVEL=“INFO”


would enable logging (INFO) for everything using printk

For the case above I would change the following in my application
.config:

CONFIG_LOG_DOMAINS=“I2C”
CONFIG_LOG_LEVEL=“DEBUG”

So this works for a simple case.  Can you expand on this for a more
complex case?  For example, let's take debugging the Galileo 2
pinmux,
which has dependencies on I2C, GPIO, and the Pinmux.  How would you
setup the DOMAINs value then and parse it?

I agree this sounds awkward.

Why aren't the component themselves providing a kconfig option that
can
be tweaked on a per-component basis.

e.g.

CONFIG_I2C_LOG_LEVEL="DEBUG"
CONFIG_PWM_LOG_LEVEL="ERROR"
CONFIG_KERNEL_LOG_LEVEL="OFF"

This allows individual files to be compiled with different log levels
by
doing this in their implementation:

in i2c.c:
#define SYS_LOG_LEVEL CONFIG_I2C_LOG_LEVEL
#include <logging.h>

in pwm.c:
#define SYS_LOG_LEVEL CONFIG_PWM_LOG_LEVEL
#include <logging.h>

in, well, all kernel files (or some common kernel-only header file):
#define SYS_LOG_LEVEL CONFIG_KERNEL_LOG_LEVEL
#include <logging.h>

Basically, this allow each subsystem to drive the logging.h logic
differently. You might not want "DEBUG" level across the whole system
because of too much verbosity, but you'd still like to have "ERROR"
level everywhere while debugging one subsystem.

My 0.02$.

+1
I'm supporting this now and will implement this on some reference
module as example for the following patch set.

On Tue, 2016-03-01 at 16:15 +0000, Chereau, Fabien wrote:

Hi,

-----Original Message-----
From: Tomasz Bursztyka [mailto:tomasz.bursztyka(a)linux.intel.com]
Sent: Tuesday, March 1, 2016 16:55
To: devel(a)lists.zephyrproject.org
Subject: [devel] Re: Re: Re: Re: Re: RFC[1/2] Common logging
infrastructure
and API

Hi Luiz,

- Another feature which is critical for Curie, is the support
of multi-core

logging. One core is the master outputting the log on the
log_backend while
other slaves cores send their logs to the master using an IPC
mechanism.
Each log message carries the information from which core it
originates, +  a
unified timestamp.

-1, this depends on the hardware architecture besides one can
write a
driver to just proxy the logs.

I don't see anything we could do about that in this logging API.
If there is something to be done, let's see it in another patch.

Indeed, my point was just to make sure at API level that such custom
implementations are pluggable.

I understand, for this first effort the goal is to unify calls under a
single API that can be later provided by different implementations. I
don't foresee conflicts between initial proposal and Fabien's insights.

- Finally, another important feature we implemented is the
buffering of

incoming logs in a circular buffer in RAM (on both master and
slave). This
allow very short log time to avoid delaying the caller of the log
function. The
logs are finally output on the log backend in a low priority task,
which reads
from the circular buffer. In case there are too many incoming logs,
some logs
are lost instead of blocking the program execution.

Provided the message order is keep that is probably ok, but if we
do
add the timestamp support then it needs to be before it enters
these
buffers. Anyway we may add timestamp support for net_buf at some
point. Btw, having it as a task probably limits this to
microkernel
only doesn't it?

Nanokernel could get it, it would run in low prio fiber and that's
it.

Imo, let's not bother fixing this right now in this API. This goes
separately.
(as I said, instead of having printk/printf we could have a new
sys_log() functions that could act
as a log buffering proxy, fully optional etc...)

Tomasz

Hi,

Hi Luiz,

- Another feature which is critical for Curie, is the support of multi-core logging. One core is the master outputting the log on the log_backend while other slaves cores send their logs to the master using an IPC mechanism. Each log message carries the information from which core it originates, + a unified timestamp.

-1, this depends on the hardware architecture besides one can write a
driver to just proxy the logs.

I don't see anything we could do about that in this logging API.
If there is something to be done, let's see it in another patch.

- Finally, another important feature we implemented is the buffering of incoming logs in a circular buffer in RAM (on both master and slave). This allow very short log time to avoid delaying the caller of the log function. The logs are finally output on the log backend in a low priority task, which reads from the circular buffer. In case there are too many incoming logs, some logs are lost instead of blocking the program execution.

Provided the message order is keep that is probably ok, but if we do
add the timestamp support then it needs to be before it enters these
buffers. Anyway we may add timestamp support for net_buf at some
point. Btw, having it as a task probably limits this to microkernel
only doesn't it?

Nanokernel could get it, it would run in low prio fiber and that's it.

Imo, let's not bother fixing this right now in this API. This goes
separately.
(as I said, instead of having printk/printf we could have a new
sys_log() functions that could act
as a log buffering proxy, fully optional etc...)

Tomasz

Hi Fabian,

On Tue, Mar 1, 2016 at 12:40 PM, Chereau, Fabien
<fabien.chereau(a)intel.com> wrote:

Hello,

FYI, in thunderdome we have also created a log system solving some of the problems you mention in your RFC. Here are my 2 cents following our experience:

- In our implementation we now support only a global log level (INFO, WARNING, ERROR) + a special DEBUG level which is activated at compile time for each module separately. Originally we also had a log level per module but it quickly proved to be mostly unused by the users, while adding some complexity (conflicts between global log levels and per module log level), so we removed it, also to save space.

Which is why I commented that having log level is not really
necessary, perhaps this is even misleading since it should always be
selected at build-time not runtime where perhaps the use of levels
makes sense.

- Another feature which is critical for Curie, is the support of multi-core logging. One core is the master outputting the log on the log_backend while other slaves cores send their logs to the master using an IPC mechanism. Each log message carries the information from which core it originates, + a unified timestamp.

-1, this depends on the hardware architecture besides one can write a
driver to just proxy the logs.

- Finally, another important feature we implemented is the buffering of incoming logs in a circular buffer in RAM (on both master and slave). This allow very short log time to avoid delaying the caller of the log function. The logs are finally output on the log backend in a low priority task, which reads from the circular buffer. In case there are too many incoming logs, some logs are lost instead of blocking the program execution.

Provided the message order is keep that is probably ok, but if we do
add the timestamp support then it needs to be before it enters these
buffers. Anyway we may add timestamp support for net_buf at some
point. Btw, having it as a task probably limits this to microkernel
only doesn't it?

Hi Fabien,

- Finally, another important feature we implemented is the buffering of incoming logs in a circular buffer in RAM (on both master and slave). This allow very short log time to avoid delaying the caller of the log function. The logs are finally output on the log backend in a low priority task, which reads from the circular buffer. In case there are too many incoming logs, some logs are lost instead of blocking the program execution.

Very good point.
We also experienced it with networking drivers where debugging in the
middle or RX/TX just kills timing.

This would need to be addressed, but besides this log macros API.

Maybe introducing a sys_log() which would be a possible LOG_FN, such
sys_log() would implement
the deferred logging. It could be optional (on some targets, it may be
difficult to get some space for such buffer).

Tomasz

Hello,

FYI, in thunderdome we have also created a log system solving some of the problems you mention in your RFC. Here are my 2 cents following our experience:

- In our implementation we now support only a global log level (INFO, WARNING, ERROR) + a special DEBUG level which is activated at compile time for each module separately. Originally we also had a log level per module but it quickly proved to be mostly unused by the users, while adding some complexity (conflicts between global log levels and per module log level), so we removed it, also to save space.

- Another feature which is critical for Curie, is the support of multi-core logging. One core is the master outputting the log on the log_backend while other slaves cores send their logs to the master using an IPC mechanism. Each log message carries the information from which core it originates, + a unified timestamp.

- Finally, another important feature we implemented is the buffering of incoming logs in a circular buffer in RAM (on both master and slave). This allow very short log time to avoid delaying the caller of the log function. The logs are finally output on the log backend in a low priority task, which reads from the circular buffer. In case there are too many incoming logs, some logs are lost instead of blocking the program execution.

Fabien

________________________________________
From: Kalowsky, Daniel [daniel.kalowsky(a)intel.com]
Sent: Monday, February 29, 2016 18:12
To: Nashif, Anas; Saucedo Tejada, Genaro; devel(a)lists.zephyrproject.org
Subject: [devel] Re: Re: RFC[1/2] Common logging infrastructure and API

-----Original Message-----
From: Nashif, Anas [mailto:anas.nashif(a)intel.com]
Sent: Sunday, February 28, 2016 4:43 AM
To: Saucedo Tejada, Genaro <genaro.saucedo.tejada(a)intel.com>;
devel(a)lists.zephyrproject.org
Subject: [devel] Re: RFC[1/2] Common logging infrastructure and API

Hi,




On 24/02/2016, 17:13, "Saucedo Tejada, Genaro"
<genaro.saucedo.tejada(a)intel.com> wrote:

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.

This is a much needed enhancement, thanks for making this proposal.

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.

We need to make sure we support logging for more than debugging and
during development. In most cases logging will be used during development
to assist with debugging and printing information on the console, however,
we need to make sure this design also addresses cases where logging is part
of the application, for example you might want to write to a file-system, send
messages to a remote endpoint or write messages to a connected display.
This basically means we also need to support different backends, the most
immediate and straightforward backend would be printing to the console
using printk and printf.

An application should be able to configure the domains and levels it wants to
log, for example, if I am debugging an issue with I2C and I am only interested
in I2C, I want to be able to select this domain and the logging level, so for
example:

the defaults:
CONFIG_LOG=y
CONFIG_LOG_BACKEND=“printk”
CONFIG_LOG_DOMAINS=“*”

CONFIG_LOG_LEVEL=“INFO”


would enable logging (INFO) for everything using printk

For the case above I would change the following in my application .config:

CONFIG_LOG_DOMAINS=“I2C”
CONFIG_LOG_LEVEL=“DEBUG”

So this works for a simple case. Can you expand on this for a more complex case? For example, let's take debugging the Galileo 2 pinmux, which has dependencies on I2C, GPIO, and the Pinmux. How would you setup the DOMAINs value then and parse it?

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"

Just use LOG_DOMAIN, no need to abbreviate this

The macros at logging.h get enabled by two definitions:
CONFIG_USE_COMPILE_LOG: This is the global Kconfig switch for logging.

Keep it simple, CONFIG_LOG, the COMPILE wording can be misleading, In
Kconfig we compile almost everything that is enabled, i.e. y means
USE_COMPILE...

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>

I think this is were things will get confusing, we do need to change all of
those existing DEBUG variables and make them work with the new model
instead of keeping them in the code. See my example above, using the right
domains and level, the same will be achieved.

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.

We should implement backends and clean up all the custom DEBUG usage in
Kconfig and move everything to the new model reducing complexity and
making things more consistent.

Please make sure we have a JIRA story to track this and add the final proposal
to that JIRA once we have reached consensus.

Anas

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)

On 29/02/2016, 12:48, "Benjamin Walsh" <benjamin.walsh(a)windriver.com> wrote:

We need to make sure we support logging for more than debugging and
during development. In most cases logging will be used during development
to assist with debugging and printing information on the console, however,
we need to make sure this design also addresses cases where logging is part
of the application, for example you might want to write to a file-system, send
messages to a remote endpoint or write messages to a connected display.
This basically means we also need to support different backends, the most
immediate and straightforward backend would be printing to the console
using printk and printf.

An application should be able to configure the domains and levels it wants to
log, for example, if I am debugging an issue with I2C and I am only interested
in I2C, I want to be able to select this domain and the logging level, so for
example:

the defaults:
CONFIG_LOG=y
CONFIG_LOG_BACKEND=“printk”
CONFIG_LOG_DOMAINS=“*”

CONFIG_LOG_LEVEL=“INFO”


would enable logging (INFO) for everything using printk

For the case above I would change the following in my application .config:

CONFIG_LOG_DOMAINS=“I2C”
CONFIG_LOG_LEVEL=“DEBUG”

So this works for a simple case. Can you expand on this for a more
complex case? For example, let's take debugging the Galileo 2 pinmux,
which has dependencies on I2C, GPIO, and the Pinmux. How would you
setup the DOMAINs value then and parse it?

I agree this sounds awkward.

Why aren't the component themselves providing a kconfig option that can
be tweaked on a per-component basis.

e.g.

CONFIG_I2C_LOG_LEVEL="DEBUG"
CONFIG_PWM_LOG_LEVEL="ERROR"
CONFIG_KERNEL_LOG_LEVEL="OFF"

This allows individual files to be compiled with different log levels by
doing this in their implementation:

in i2c.c:
#define SYS_LOG_LEVEL CONFIG_I2C_LOG_LEVEL
#include <logging.h>

in pwm.c:
#define SYS_LOG_LEVEL CONFIG_PWM_LOG_LEVEL
#include <logging.h>

in, well, all kernel files (or some common kernel-only header file):
#define SYS_LOG_LEVEL CONFIG_KERNEL_LOG_LEVEL
#include <logging.h>

Basically, this allow each subsystem to drive the logging.h logic
differently. You might not want "DEBUG" level across the whole system
because of too much verbosity, but you'd still like to have "ERROR"
level everywhere while debugging one subsystem.

My 0.02$.

+1

This sounds more scalable, basically removes the need for defining a domain and using the levels to do the selection of how verbose messages are for each domain.

Anas

On 02/29/2016 09:48 AM, Benjamin Walsh wrote:

We need to make sure we support logging for more than debugging and
during development. In most cases logging will be used during development
to assist with debugging and printing information on the console, however,
we need to make sure this design also addresses cases where logging is part
of the application, for example you might want to write to a file-system, send
messages to a remote endpoint or write messages to a connected display.
This basically means we also need to support different backends, the most
immediate and straightforward backend would be printing to the console
using printk and printf.

An application should be able to configure the domains and levels it wants to
log, for example, if I am debugging an issue with I2C and I am only interested
in I2C, I want to be able to select this domain and the logging level, so for
example:

the defaults:
CONFIG_LOG=y
CONFIG_LOG_BACKEND=“printk”
CONFIG_LOG_DOMAINS=“*”

CONFIG_LOG_LEVEL=“INFO”


would enable logging (INFO) for everything using printk

For the case above I would change the following in my application .config:

CONFIG_LOG_DOMAINS=“I2C”
CONFIG_LOG_LEVEL=“DEBUG”

So this works for a simple case. Can you expand on this for a more
complex case? For example, let's take debugging the Galileo 2 pinmux,
which has dependencies on I2C, GPIO, and the Pinmux. How would you
setup the DOMAINs value then and parse it?

I agree this sounds awkward.

Why aren't the component themselves providing a kconfig option that can
be tweaked on a per-component basis.

e.g.

CONFIG_I2C_LOG_LEVEL="DEBUG"
CONFIG_PWM_LOG_LEVEL="ERROR"
CONFIG_KERNEL_LOG_LEVEL="OFF"

This allows individual files to be compiled with different log levels by
doing this in their implementation:

in i2c.c:
#define SYS_LOG_LEVEL CONFIG_I2C_LOG_LEVEL
#include <logging.h>

in pwm.c:
#define SYS_LOG_LEVEL CONFIG_PWM_LOG_LEVEL
#include <logging.h>

in, well, all kernel files (or some common kernel-only header file):
#define SYS_LOG_LEVEL CONFIG_KERNEL_LOG_LEVEL
#include <logging.h>

Basically, this allow each subsystem to drive the logging.h logic
differently. You might not want "DEBUG" level across the whole system
because of too much verbosity, but you'd still like to have "ERROR"
level everywhere while debugging one subsystem.

+1 Said the same thing although not as well in my response you dan and I
must have been typing at the same time :-)

My 0.02$.

We need to make sure we support logging for more than debugging and
during development. In most cases logging will be used during development
to assist with debugging and printing information on the console, however,
we need to make sure this design also addresses cases where logging is part
of the application, for example you might want to write to a file-system, send
messages to a remote endpoint or write messages to a connected display.
This basically means we also need to support different backends, the most
immediate and straightforward backend would be printing to the console
using printk and printf.

An application should be able to configure the domains and levels it wants to
log, for example, if I am debugging an issue with I2C and I am only interested
in I2C, I want to be able to select this domain and the logging level, so for
example:

the defaults:
CONFIG_LOG=y
CONFIG_LOG_BACKEND=“printk”
CONFIG_LOG_DOMAINS=“*”

CONFIG_LOG_LEVEL=“INFO”


would enable logging (INFO) for everything using printk

For the case above I would change the following in my application .config:

CONFIG_LOG_DOMAINS=“I2C”
CONFIG_LOG_LEVEL=“DEBUG”

So this works for a simple case. Can you expand on this for a more
complex case? For example, let's take debugging the Galileo 2 pinmux,
which has dependencies on I2C, GPIO, and the Pinmux. How would you
setup the DOMAINs value then and parse it?

I agree this sounds awkward.

Why aren't the component themselves providing a kconfig option that can
be tweaked on a per-component basis.

e.g.

CONFIG_I2C_LOG_LEVEL="DEBUG"
CONFIG_PWM_LOG_LEVEL="ERROR"
CONFIG_KERNEL_LOG_LEVEL="OFF"

This allows individual files to be compiled with different log levels by
doing this in their implementation:

in i2c.c:
#define SYS_LOG_LEVEL CONFIG_I2C_LOG_LEVEL
#include <logging.h>

in pwm.c:
#define SYS_LOG_LEVEL CONFIG_PWM_LOG_LEVEL
#include <logging.h>

in, well, all kernel files (or some common kernel-only header file):
#define SYS_LOG_LEVEL CONFIG_KERNEL_LOG_LEVEL
#include <logging.h>

Basically, this allow each subsystem to drive the logging.h logic
differently. You might not want "DEBUG" level across the whole system
because of too much verbosity, but you'd still like to have "ERROR"
level everywhere while debugging one subsystem.

My 0.02$.

On 02/28/2016 04:42 AM, Nashif, Anas wrote:

Hi,

Anas please fix you email client to set in-reply-to: correctly
so threading work correctly.

On 24/02/2016, 17:13, "Saucedo Tejada, Genaro" <genaro.saucedo.tejada(a)intel.com> wrote:

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.

This is a much needed enhancement, thanks for making this proposal.

Agreed we need to have a common facility.

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.

We need to make sure we support logging for more than debugging and during
development. In most cases logging will be used during development to assist
with debugging and printing information on the console, however, we need to
make sure this design also addresses cases where logging is part of the application,
for example you might want to write to a file-system, send messages to a remote
endpoint or write messages to a connected display. This basically means we also
need to support different backends, the most immediate and straightforward
backend would be printing to the console using printk and printf.

So the logging driver could bind to the appropriate backend/output
device by name configured at compile time.

An application should be able to configure the domains and levels it wants to
log, for example, if I am debugging an issue with I2C and I am only interested
in I2C, I want to be able to select this domain and the logging level, so for example:

the defaults:
CONFIG_LOG=y
CONFIG_LOG_BACKEND=“printk”
CONFIG_LOG_DOMAINS=“*”

CONFIG_LOG_LEVEL=“INFO”

We need to differentiate the name of this API from the logging facility
we already have one the the APIs name needs to change :-)

would enable logging (INFO) for everything using printk

For the case above I would change the following in my application .config:

CONFIG_LOG_DOMAINS=“I2C”
CONFIG_LOG_LEVEL=“DEBUG”

How would we handle a list of domains to be logged? i.e. "I2C, SPI ..."
I think it is more straight forward to let the developer/integrator
decide which modules/domains/drivers have logging turned on.

Your proposal is nice and general but would require a fair amount
of decision making over and above level which should probalbly
be per domain 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"

Just use LOG_DOMAIN, no need to abbreviate this

The macros at logging.h get enabled by two definitions:
CONFIG_USE_COMPILE_LOG: This is the global Kconfig switch for logging.

Keep it simple, CONFIG_LOG, the COMPILE wording can be misleading, In Kconfig we compile almost everything that is enabled, i.e. y means USE_COMPILE...

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>

I think this is were things will get confusing, we do need to change all of those existing DEBUG variables and make them work with the new model instead of keeping them in the code. See my example above, using the right domains and level, the same will be achieved.

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.

We should implement backends and clean up all the custom DEBUG usage in Kconfig and move everything to the new model reducing complexity and making things more consistent.

Please make sure we have a JIRA story to track this and add the final proposal to that JIRA once we have reached consensus.

Anas

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)

Hi,




On 24/02/2016, 17:13, "Saucedo Tejada, Genaro" <genaro.saucedo.tejada(a)intel.com> wrote:

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.

This is a much needed enhancement, thanks for making this proposal.

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.

We need to make sure we support logging for more than debugging and during development. In most cases logging will be used during development to assist with debugging and printing information on the console, however, we need to make sure this design also addresses cases where logging is part of the application, for example you might want to write to a file-system, send messages to a remote endpoint or write messages to a connected display. This basically means we also need to support different backends, the most immediate and straightforward backend would be printing to the console using printk and printf.

An application should be able to configure the domains and levels it wants to log, for example, if I am debugging an issue with I2C and I am only interested in I2C, I want to be able to select this domain and the logging level, so for example:

the defaults:
CONFIG_LOG=y
CONFIG_LOG_BACKEND=“printk”
CONFIG_LOG_DOMAINS=“*”

CONFIG_LOG_LEVEL=“INFO”


would enable logging (INFO) for everything using printk

For the case above I would change the following in my application .config:

CONFIG_LOG_DOMAINS=“I2C”
CONFIG_LOG_LEVEL=“DEBUG”

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"

Just use LOG_DOMAIN, no need to abbreviate this

The macros at logging.h get enabled by two definitions:
CONFIG_USE_COMPILE_LOG: This is the global Kconfig switch for logging.

Keep it simple, CONFIG_LOG, the COMPILE wording can be misleading, In Kconfig we compile almost everything that is enabled, i.e. y means USE_COMPILE...

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>

I think this is were things will get confusing, we do need to change all of those existing DEBUG variables and make them work with the new model instead of keeping them in the code. See my example above, using the right domains and level, the same will be achieved.

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.

We should implement backends and clean up all the custom DEBUG usage in Kconfig and move everything to the new model reducing complexity and making things more consistent.

Please make sure we have a JIRA story to track this and add the final proposal to that JIRA once we have reached consensus.

Anas

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)

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)