Retire your debugger, log smartly with Log::Log4perl!
by Michael Schilli
|
Pages: 1, 2, 3, 4
Layouts
If we want to get fancier (the previously shown :easy target did this behind our back), then we need to use the more flexible PatternLayout
instead. It takes a format string as an argument, in which it will --
similar to printf() -- replace a number of placeholders by
their actual values when it comes down to log the message. Here's how to
attach a layout to our appender:
# Layouts
my $layout =
Log::Log4perl::Layout::PatternLayout->new(
"%d %p> %F{1}:%L %M - %m%n");
$appender->layout($layout);
Since %d stands for date and time, %p for priority, %F for
the source file name, %M for the method executed,
%m for the log message and %n for a newline, this
layout will cause the appender to write the message like this:
2002/08/06 08:26:23 INFO> eat:56 Groceries::Food::consume - Eating Sushi
The %F{1} is special in that it takes the right-most component of the file, which
usually consists of the full path -- just like the
basename() function does.
That's it -- we've got Log::Log4perl ready for the big league. Listing
eat.pl shows the entire "system": Startup code, the main program and the
application wrapped into the Groceries::Food class.
Listing 2: eat.pl
01 ######### System initialization section ###
02 use Log::Log4perl qw(get_logger :levels);
03
04 my $food_logger = get_logger("Groceries::Food");
05 $food_logger->level($INFO);
06
07 # Appenders
08 my $appender = Log::Log4perl::Appender->new(
09 "Log::Dispatch::File",
10 filename => "test.log",
11 mode => "append",
12 );
13
14 $food_logger->add_appender($appender);
15
16 # Layouts
17 my $layout =
18 Log::Log4perl::Layout::PatternLayout->new(
19 "%d %p> %F{1}:%L %M - %m%n");
20 $appender->layout($layout);
21
22 ######### Run it ##########################
23 my $food = Groceries::Food->new("Sushi");
24 $food->consume();
25
26 ######### Application section #############
27 package Groceries::Food;
28
29 use Log::Log4perl qw(get_logger);
30
31 sub new {
32 my($class, $what) = @_;
33
34 my $logger = get_logger("Groceries::Food");
35
36 if(defined $what) {
37 $logger->debug("New food: $what");
38 return bless { what => $what }, $class;
39 }
40
41 $logger->error("No food defined");
42 return undef;
43 }
44
45 sub consume {
46 my($self) = @_;
47
48 my $logger = get_logger("Groceries::Food");
49 $logger->info("Eating $self->{what}");
50 }
Beginner's Pitfalls
Remember when we said that if a logger decides to fire, then it forwards the message to all of its appenders and also has it bubble up the hierarchy to hit all other appenders it meets on the way up?
Don't underestimate the ramifications of this statement. It usually puzzles Log::Log4perl beginners. Imagine the following logging requirements for a new system:
- Messages of level FATAL are supposed to be written to STDERR, no matter which subsystem has issued them.
-
Messages issued by the
Groceriescategory, priorized DEBUG and higher need to be appended to a log file for debugging purposes.
Easy enough: Let's set the root logger to FATAL and attach a Log::Dispatch::Screen appender to it. Then, let's set the Groceries logger to DEBUG and attach a Log::Dispatch::File appender to it.
 |
| Figure 2: A Groceries::Food and a root appender |
Now, if any logger anywhere in the system issues a FATAL message and decides to 'fire,' the message will bubble up to the top of the
logger hierarchy, be caught by every appender on the way and ultimately
end up at the root logger's appender, which will write it to STDERR as
required. Nice.
But what happens to DEBUG messages originating within Groceries? Not only will the Groceries logger 'fire' and forward the message to its appender, but it will also
percolate up the hierarchy and end up at the appender attached to the root
logger. And, it's going to fill up STDERR with DEBUG messages from Groceries, whoa!
This kind of unwanted appender chain reaction causes duplicated logs. Here's two mechanisms to keep it in check:
-
Each appender carries an additivity flag. If this is set to a false value, like in
$appender->additivity(0);then the message won't bubble up further in the hierarchy after the appender is finished.
-
Each appender can define a so-called appender threshold, a minimum level required for an oncoming message to be honored by the appender:
$appender->threshold($ERROR);If the level doesn't meet the appender's threshold, then it is simply ignored by this appender.
In the case above, setting the additivity flag of the
Groceries-Appender to a false value won't have the desired effect, because it will
stop FATAL messages of the Groceries category to be forwarded to the root appender. However, setting the root
logger's threshold to FATAL will do the trick: DEBUG messages bubbling up from Groceries will simply be ignored.
Compact Logger Setups With Configuration Files
Configuring Log::Log4perl can be accomplished outside of your program in a configuration file. In
fact, this is the most compact and the most common way of specifying the
behavior of your loggers. Because Log::Log4perl originated out of the Java-based log4j system, it understands log4j configuration files:
log4perl.logger.Groceries=DEBUG, A1
log4perl.appender.A1=Log::Dispatch::File
log4perl.appender.A1.filename=test.log
log4perl.appender.A1.mode=append
log4perl.appender.A1.layout=Log::Log4perl::Layout::PatternLayout
log4perl.appender.A1.layout.ConversionPattern=%d %p> %F{1}:%L %M - %m%n
This defines a logger of the category Groceries, whichs priority is set to DEBUG. It has the appender A1 attached to it, which is later resolved to be a new Log::Dispatch::File appender with various settings and a PatternLayout with a user-defined
format (ConversionPattern).
If you store this in eat.conf and initialize your system with
Log::Log4perl->init("eat.conf");
then you're done. The system's compact logging setup is now separated from the application and can be easily modified by people who don't need to be familiar with the code, let alone Perl.
Or, if you store the configuration description in $string, then you can initialize it with
Log::Log4perl->init(\$string);
You can even have your application check the configuration file in regular intervals (this obviously works only with files, not with strings):
Log::Log4perl->init_and_watch("eat.conf", 60);
checks eat.conf every 60 seconds upon log requests and reloads everything and
re-initializes itself if it detects a change in the configuration file.
With this, it's possible to tune your logger settings while the system is running without restarting it!
The compatibility of Log::Log4perl with log4j goes so far that
Log::Log4perl even understands log4j
Java classes as appenders and maps them, if possible, to the corresponding
ones in the Log::Dispatch namespace.
Log::Log4perl will happily process the following Java-fied version of the configuration
shown at the beginning of this section:
log4j.logger.Groceries=DEBUG, A1
log4j.appender.A1=org.apache.log4j.FileAppender
log4j.appender.A1.File=test.log
log4j.appender.A1.layout=org.apache.log4j.PatternLayout
log4j.appender.A1.layout.ConversionPattern=%F %L %p %t %c - %m%n
The Java-specific FileAppender class will be mapped by Log::Log4perl
to Log::Dispatch::File behind the scenes and the parameters adjusted (The Java-specific File will become filename and an additional parameter
mode will be set to "append" for the Log::Dispatch world).
