[log4perl-devel] Log::Log4perl Recipe of the Week (#11)

[<log...@pe...>]

Welcome to the Log::Log4perl recipe of the week. Today:

============================================================
Log::Log4perl Recipe of the Week (#11):

I keep getting duplicate log messages! What's wrong?
============================================================

Having several settings for related categories in the
Log4perl configuration file sometimes leads to a phenomenon
called "message duplication". It can be very confusing at
first, but if thought through properly, it turns out that
Log4perl behaves as advertised. But, don't despair, of
course there's a number of ways to avoid message duplication
in your logs.

Here's a sample Log4perl configuration file that produces
the phenomenon:

    log4perl.logger.Cat        = ERROR, Screen
    log4perl.logger.Cat.Subcat = WARN, Screen

    log4perl.appender.Screen   = Log::Dispatch::Screen
    log4perl.appender.Screen.layout = SimpleLayout

It defines two loggers, one for category "Cat" and one for
"Cat::Subcat", which is obviously a subcategory of "Cat".
The parent logger has a priority setting of ERROR, the child
is set to the lower "WARN" level.

Now imagine the following code in your program:

    my $logger = get_logger("Cat.Subcat");
    $logger->warn("Warning!");

What do you think will happen? An unexperienced Log4perl
user might think: "Well, the message is being sent with
level WARN, so the "Cat::Subcat" logger will accept it and
forward it to the attached "Screen" appender. Then, the
message will percolate up the logger hierarchy, find the
"Cat" logger, which will suppress the message because of its
ERROR setting." But, perhaps surprisingly, what you'll get
with the code snippet above is not one but two log messages
written to the screen:

    WARN - Warning!
    WARN - Warning!

What happened? The culprit is that once the logger
"Cat::Subcat" decides to fire, it will forward the message
*unconditionally* to all directly or indirectly attached
appenders. The "Cat" logger will never be asked if it wants
the message or not -- the message will just be pushed
through to the appender attached to "Cat".

One way to prevent the message from bubbling up the logger
hierarchy is to set the "additivity" flag of the subordinate
logger to 0:

    log4perl.logger.Cat            = ERROR, Screen
    log4perl.logger.Cat.Subcat     = WARN, Screen
    log4perl.additivity.Cat.Subcat = 0

    log4perl.appender.Screen   = Log::Dispatch::Screen
    log4perl.appender.Screen.layout = SimpleLayout

The message will now be accepted by the "Cat::Subcat"
logger, forwarded to its appender, but then "Cat::Subcat"
will suppress any further action. While this setting avoids
duplicate messages as seen before, it is often not the
desired behaviour. Messages percolating up the hierarchy are
a useful Log4perl feature.

If you're defining *different* appenders for the two
loggers, one other option is to define an appender threshold
for the higher-level appender. Typically it is set to be
equal to the logger's level setting:

    log4perl.logger.Cat           = ERROR, Screen1
    log4perl.logger.Cat.Subcat    = WARN, Screen2

    log4perl.appender.Screen1   = Log::Dispatch::Screen
    log4perl.appender.Screen1.layout = SimpleLayout
    log4perl.appender.Screen1.Threshold = ERROR

    log4perl.appender.Screen2   = Log::Dispatch::Screen
    log4perl.appender.Screen2.layout = SimpleLayout

Since the "Screen1" appender now blocks every message with a
priority less than ERROR, even if the logger in charge lets
it through, the message percolating up the hierarchy is
being blocked at the last minute and *not* appended to
"Screen1".

So far, we've been operating well within the boundaries of
the Log4j standard, which Log4perl adheres to. However, if
you would really, really like to use a single appender and
keep the message percolation intact without having to deal
with message duplication, there's a non-standard solution
for you:

    log4perl.logger.Cat        = ERROR, Screen
    log4perl.logger.Cat.Subcat = WARN, Screen

    log4perl.appender.Screen   = Log::Dispatch::Screen
    log4perl.appender.Screen.layout = SimpleLayout

    log4perl.oneMessagePerAppender = 1

The "oneMessagePerAppender" flag will suppress duplicate
messages to the same appender. Again, that's non-standard.
But way cool :).


Have fun! Until next week.

-- Mike

###################################
# Mike Schilli                    #
# log...@pe...        #
# http://perlmeister.com          #
# http://log4perl.sourceforge.net #
###################################