Here I want to describe how I plan to refactor the logging back end
implementation for imag.
This post was published on imag-pim.org as well as
on my personal blog.
What we have
Right now, the logging implementation is ridiculously simple. What we do is:
On every call to one of the logging macros, the log crate gives us an object
with a few informations (line number, file, log message,...) – we apply our
format, some color and write it to stderr.
This is of course rather simple and not really flexible.
What we want to have
I want to rewrite the logging backend to give the user more power about the
logging. As we only have to rewrite the backend, and the log crate handles
everything else, the actual logging looks non different and “client” code does
not change.
+----------------------------+
| imag code, libs, bins, ... |
+----------------------------+
|
| calls
|
v
+----------------------------+
| crate: "log" |
+----------------------------+
|
| calls
|
v
+----------------------------+
| imag logging backend impl. |
+----------------------------+
So what features do we want?
First of all, the imag user must be able to configure the logging.
Not only with the configuration file but also via environment
variables and of course command line parameters. The former will be overridden
by the latter, respectively. This gives the user nice control, as she can
configure imag to log to stderr with only warnings being logged but when calling
a script of imag commands or calling imag directly from the command line, these
settings can be temporarily (for the script or one command) be overridden.
The configuration options I have in mind are best described by an example:
# The logging section of the configuration
[logging]
# the default logging level
# Valid values are "trace", "debug", "info", "warn", "error"
level = "debug"
# the destinations of the logging output.
# "-" is for stderr, multiple destinations are possible
default-destinations = [ "-", "/tmp/imag.log" ]
# The format for the logging output
#
# The format supports variables which are inserted for each logging call:
#
# "%no%" - The of the logging call
# "%thread%" - The thread id from the thread calling the log
# "%level%" - The logging level
# "%module%" - The module name
# "%file%" - The file path where the logging call appeared
# "%line%" - The line No of the logging call
# "%message%"" - The logging message
#
# Functions can be applied to the variables to change the color of
# the substitutions.
#
# A format _must_ contain "%message%, else imag fails because no logging should
# be forbidden
#
[logging.formats]
trace = "cyan([imag][%no%][%thread%][%level%][%module%][%file%][%line%]): %message%"
debug = "cyan([imag][%no%][%thread%][%level%][%module%][%file%][%line%]): %message%"
info = "[imag]: %message%"
warn = "red([imag]:) %message%"
error = "red(blinking([imag][uppercase(%level%)]): %message%)"
# Example entry for one imag module
# If a module is not configured or keys are missing
# the default values from above are applied
[logging.modules.libimagstore]
enabled = true
level = "trace"
destinations = [ "-" ]
# A format is only globally configurable, not per-module
One of the most complex things in here would be the format parsing, as variable
expansion and functions to apply are some kind of DSL I have to implement.
I hope I can do this – maybe there's even a crate for helping me with this?
Maybe the shellexpand
library will do?
These things and configuration options give the user great power over the
logging.
The approach
Because imag already logs a lot, I think about an approach where one thread is
used for the actual logging. Because each logging call involves a lot of
complexity, I want to move that to a dedicated thread where other threads speak
to the logging thread via a MPSC queue.
Of course, this should be opt-in.
The idea is that the logging starts a thread upon construction (which is really
early in the imag process, nearly one of the first operations done). This
happens when the Runtime object is build and hence no “client code” has to be
changed, all changes remain in libimagrt.
This thread is bound to the Runtime object, logging calls (via the logging
backend which is implemented for the log crate) talk to it via a channel. The
thread then does the heavy lifting. Of course, configuration can be aggregated
on construction of the logging thread.
The logging thread is killed when the Runtime object is dropped (one of the
last operations in each imag process). Of course, the queue has to be emptied
before the logging is closed.
I am also thinking about converting the code base to use the slog crate, which
offers structured logging. But I'm not yet sure whether we will benefit from
that, because I don't know whether we would need to pass a state-object around.
If that is the case, I cannot do this as this would introduce a lot of
complexity which I don't want to have. If no such object needs to be passed
around, I still have to evaluate whether the slog crate is a nice idea and of
course this would also increase the number of (complex) dependencies by one...
and I'm not sure whether the benefits outrule the inconveniences.
tags: #linux #open source #programming #rust #software #tools #imag