Re: [boost] [log] Boost.Log formal review ongoing

Subject: Re: [boost] [log] Boost.Log formal review ongoing
From: Darryl Green (darryl.green_at_[hidden])
Date: 2010-03-12 09:05:11

Just a quick (ok quite long) note / questions at this stage.

Currently we have applications using a logging lib that uses a channel
model exclusively. By that I mean there are no message attributes - all
routing/filtering of messages between sources and sinks is performed
based not on message content but by source identity. Sources are named.
We create sources with names like (this isn't the only form supported
but is a common one) "module.component.instance.severity".

The routing/filtering is done using a simple pattern match on the source
name. Configuration data is simply a list of patterns associated with a
sink and used to determining if a given source is connected to a sink.

so a typical config (filter) for a sink might be

*.error
comms.clientsession.*
comms.clientsession.*.trace-
comms.clientsession.*.debug-
comms.clientsession.clientid1.*

which would result in all errors being logged, along with severities
other that trace and debug for all comms clientsessions being logged and
all messages form clientid1 (ie including trance and debug messages)
being logged.

In this scheme creating a log source is relatively expensive as it
attempts to match the source to the configured routing "rules", but once
it has done so the result (connected or not to a given sink) is cached.

Changing the config dynamically (something we use a lot) is very
expensive as it requires that all sources be re-evaluated as above.
However this is mitigated by the fact that we don't care exactly when
the change is applied, only that it is applied eventually, and the
logging system allows the rule eval/update to be done asynchronously to
logging with only a small (pointer swap) operation to apply the new rule
to a source being performed while holding a lock.

Adding/removing sinks is logically just a variation on the dynamic
config change case.

The code in some cases contains enough logging/expensive enough data
gathering that configuring "*" will bring the system performance down to
an unusable level (and generate an unusable amount of data).

Because the channel evaluation is done only on creation of source and
change in log configuration (and the latter is async) the cost of
logging something that will in not be sent anywhere is very low
(comparing a pointer to null). 

The use pattern is that a given class has a set of sources (one per
severity). When an object that logs is constructed (though in some cases
it defers or changes the "naming" of the instance later (eg when a
session is fully established with a client such that the client name can
be associated  with the server object).

Sources that are named the same are effectively the same for logging
purposes (but need have no knowledge of each others existence) - this is
similar in effect to applying the same attributes to messages (but via
different loggers) in boost.log.
 
The logging system does not support sink specific formatting (beyond
simple prepending of things like time stamps) - the log "message" is a
preformatted string. We had ideas we might change that but haven't as
yet found the need.

Anyway - I've looked at the docs for boost.log and read some review
comments to see if we could replace this with the proposed boost.log.
I've reached the following (possibly wrong) conclusions:

1) there isn't a direct mapping from this style of logging
2) the obvious approach of making each element of the channel identifier
an attribute would seem ok - but I'm concerned that the cost of
evaluating the filters would be significant
3) formatting features are nice
4) it isn't immediately clear how to support dynamic configuration of
"filtering" and sinks
5) attributes seem a little overloaded - the attribute as something to
be filtered on and the attribute as something to be included in
(formatted in to) the logged message roles are potentially different. It
would be nice to have expensive to evaluate attributes that played no
role in filtering but that were (after filtering "passed" the message)
evaluated conditionally based on filtering.
6) There are use cases that boost.log can support (ones where the
filtering is based on more "dynamic" attributes) that are not practical
to support in the pure channel based model afaiks. I'd class most of
these as "alarms" where there is some sort of thresholding or similar
criteria applied to an attribute value (or combinations) to determine
whether to log the message.

At this point I suspect (I would need to run some benchamrks) that
boost.log won't suit the uses cases I currently have, but is (subject to
some concerns which might be unfounded re support for dynamic
configuration) flexible enough to support far more use cases than what
I'm using at present - at least when the performance in the case where
the message is to be discarded is less critical.

Unless I have more time suddenly appear from nowhere I probably won't be
able to do a proper review, but I would be really interested in any
feedback on whether this usage is supported (and how) by boost.log.

Darryl