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

The logging system is composed of three parts: logger service, logset utility and the application using the logging.

The logger service is an init task and it takes care of printing the messages and also remembers the reporting levels for each log.

The logset utility is a front-end to the logger that can change the reporting levels of existing logs. The same can be done through a C API from <io/logctl.h>.

The application uses API from libc to create logs and send log messages to the logger.

To prevent sending the whole message even if it is not going to be printed, the logger may respond to the initial LOGGER_WRITER_MESSAGE with ENAK to signal that it is useless to send the buffer.

Assorted thoughts for improvements

The logger can easily become a bottleneck of the whole logging system. Maybe the client themselves shall write the messages to the file and logger would only forward reporting level changes to the applications.

However, this way it would be easier to add another target where the messages would be stored - e. g. it might be interesting to be able to send the messages over network. Maybe logger shall only forward the buffers?

If it would turn out that even the not-printed debug messages slow down the system too much, it might be possible to limit even more the number of IPC messages and asprintf calls. There could be a dedicated fibril that would connect to the logger and would only send message reply-when-level-changed that the logger would answer only if there would be a change of the reported level in one of the logs. This fibril would then propagate this information into the locally stored log_t and log_msg() would be able to return much earlier. Also, if the function log_msg() would be replaced with a macro, there would be no need to format the message at all if the message would not be going to be printed. Below is an idea how to do such macro.

#define log_msg(log, level, ...) \
   if (_log_enabled(log, level)) { \
       _log_msg(log, level, __VA_ARGS__); \
   }

Note that the above was partially implemented during rewriting of the logging system but was later discarded because of bugs.