Logging functions in HelenOS

If you want to use some kind of logging - either for debugging purposes or to report errors - consider using the one provided in libc. The current implementation does not offer any spectacular features but shall be sufficient for most cases.

The logging messages are printed to screen (depending on kernel configuration) and are also written to files. To prevent flooding of the system with logging messages, the messages are assigned severity levels (see table below) and the user specifies how verbose the system shall be - i.e. to which detail are the messages actually printed. To allow more fine-grained tuning of what-to-print, the messages are directed to different logs that form a tree-like structure. It is possible to control reporting level (verbosity) of each log separately, giving user the ability to exactly specify which part of the system shall be monitored in the greatest detail.

For example, a (hypothetical) USB keyboard driver can offer a separate log for each keyboard that is plugged in. Thus, user trying to find out why his special button does not work can specify that all messages for the special keyboard shall be printed but also suppress any other messages - namely from the other keyboard that works and which is used to control the system.

Currently, following levels are recognised.

Name	Typical usage
LVL_FATAL	Fatal error, program is not able to recover at all.
LVL_ERROR	Serious error but the program can recover from it. E.g. driver cannot control one device but otherwise is healthy.
LVL_WARN	Easily recoverable problem, such as one corrupted packet that can be skipped.
LVL_NOTE	Message that does not indicate a problem, but should be printed at the default logging level.
LVL_DEBUG	Debugging-purpose message. Not printed at the default logging level. Increasing logging level to LVL_DEBUG should not swamp the log.
LVL_DEBUG2	More detailed debugging message.

By default, messages with level LVL_NOTE and above (i. e. warning and errors) are printed. To see the debugging messages, the user has to enable them: see below how to increase the verbosity level at boot-time and at run-time.

Going through existing logs

All logs are stored under the /log/ directory and file name corresponds to the server/application where the messages originated. To examine these files, one can use edit or cat.

The file contains the whole tree of the logs - each line is prefixed with severity level of the message and name of the log.

Example: running tester application with logger1 test shall create a /log/tester file with dummy messages. The test tries to print message at every severity level, what is actually stored into the file depends on current settings (see below for more examples).

Changing reported level at boot-time

The following currently works only for GRUB-based platforms.

To change the default reporting level, simply add its name (e. g. fatal or debug2) after the logger module load in the GRUB.

Example (making default reporting level less verbose): append the word warn to the logger module line once the GRUB menu appears (use e to enter the edit mode).

module /boot/logger /boot/logger warn

Then use F10 to boot HelenOS.

It is also possible to change reporting level of an individual log. Simply write the log name and append to it the desired level. This can be repeated for more logs.

Example (making tester very verbose): change the logger line to the following.

module /boot/logger /boot/logger tester=debug2

Both possibilities can be combined. For example, it is possible to set the default reporting level to errors only and only make several (problematic) drivers more verbose.

Changing reported level at run-time

It is also possible to change reported log level at run-time. For that the user shall use the logset utility. The utility is controlled purely via its command-line arguments - one of them is always the name of the level that is supposed to be set.

To change the default reporting level, simply run logset with the level name - following would make the system very quiet.

logset fatal

To change the reporting level of a certain log, run logset with the log name followed by the level name. For example, to make devman more verbose, run the following:

logset devman debug2

It is also possibly to target a nested log - simply separate individual names with a slash (like in a file name).

Example (tester logger2): To demonstrate how setting log levels at run-time works, you shall open at least three terminals. In one, start the tester with logger2 test. This test only prints messages at different levels to different logs.

In the second, you shall monitor the tester log - either by catting /log/tester or you can switch to kernel console (if you configure HelenOS without GUI, seventh console shall display that output).

And in the third console you can issue the logset to see what happens.

By default, you would see that tester continuously prints errors, warnings and notes into three logs: the default one (i. e. tester), alpha and bravo (tester/alpha and tester/alpha/bravo).

Running

logset tester/alpha fatal

would mute all the output to alpha and alpha/bravo logs. The reason why bravo was muted as well is because it is a child of alpha and has to respect its settings (unless explicitly overridden).

But it is possible to explicitly enable bravo output. If we ran

logset tester/alpha/bravo warn

the alpha is still muted but together with the original tester messages, bravo warnings are interleaved.

Using the C API

To use the logging functions, include <io/log.h> into your source files. Before logging can be used, you have to initialize the logging subsystem by calling log_init(). This function takes the log name as an argument. It would be typically name of your application.

For example, our tester application is initialized with

log_init("tester");

Once the logging is initialized, you may use the log_msg() which actually prints the messages. The log_msg is a printf-like function, first arguments are the target log and the level of the message. For starters, you may use the default log LOG_DEFAULT.

Following code prints the pointer address if the reporting level is at least debug.

void *p = malloc(...);
log_msg(LOG_DEFAULT, LVL_DEBUG, "Allocated at %p.", p);

Notice that there is no new-line at the end of the message. The new-line is automatically appended before writing the message to the file.

To create a sub-log, use the log_create() function. It takes two arguments - log name and its parent log. The parent log could be either LOG_DEFAULT or log created during previous call to log_create(). Note that log_create() always returns a valid log_t. A footnote: yes, log creation can fail but rarely and the worst thing that can happen is that the messages would go to the parent which is not that big problem.

Example:

...
#include <io/log.h>

...

int main(int argc, char *argv[])
{
    log_init("myapp");

    /* The alpha log would be directly under the default log. */
    log_t log_alpha = log_create("alpha", LOG_DEFAULT);

    /* The bravo log would be under alpha. */
    log_t log_bravo = log_create("bravo", log_alpha);


    log_msg(LOG_DEFAULT, LVL_WARN, "Dummy warning.");

    /* ... */

    log_msg(log_alpha, LVL_NOTE, "Alpha is running.");

    /* Notice how log_t is printed. */
    log_msg(log_bravo, LVL_DEBUG2, "This log id is %" PRIlogctx ".", log_bravo);

    /* ... */
}

Behind the scene

TODO - how logger, logset and log_*() works