Logging is recording messages from my program so I can watch its progress or look at what happened later. This is much larger than recording warnings or errors from my program since I can also log messages when things are going well, instead of just when things don’t work. Along with configuration, logging is one of the features missing from most Perl applications, but it’s incredibly easy to add.
Web applications already have it made. They can send things to STDERR (through
whichever mechanism or interface the program might use), and they show up
in the web server error log.[48]Other programs have to work harder. In general, logging is
not as simple as opening a file, appending some information, and closing
the file. That might work if the program won’t run more than once at the
same time and definitely finishes before it will run again. For any other
case, it’s possible that two runs of the program running at the same time
will try to write to the same file. Output buffering and the race for
control of the output file mean that somebody is going to win, and not all
of the output may make it into the file.
Logging, however, doesn’t necessarily mean just adding something to a file. Maybe I want to shove the messages into a database, show them on the screen, send them to a system logger (such as syslogd), or more than one of those. I might want to send them directly to my email or pager. Indeed, if something is going wrong on one machine, to ensure that I see the message I might want to send it to another machine. I might want to send a message to several places at the same time. Not only should it show up in the logfile, but it should show up on my screen. I might want different parts of my program to log things differently. Application errors might go to customer service people while database problems go to the database administrators.
If that’s not complicated enough, I might want different levels of logging. By assigning messages an importance, I can decide which messages I want to log. For instance, I might have a debugging level that outputs quite a bit of information because I want to see as much as possible when I need to fix a problem. When I put my program into production, I don’t want to fill up my log with that extra debugging information, but I still want to see other important messages.
Putting all of that together, I need:
Output to multiple places
Different logging for different program parts
Different levels of logging
There are several modules that can handle all of those, including
Michael Schilli’s Log::Log4perl
and Dave Rolsky’s Log::Dispatch, but I’m
only going to talk about one of them. Once I have the basic concept, I do
the same thing with only minor interface details. Indeed, parts of
Log::Log4perl use
Log::Dispatch.
The Apache/Jakarta project created a Java logging mechanism called log4j, which has all of the features I
mentioned in the last section. Language wars aside, it’s a nice package.
It’s so nice, in fact, that Mike Schilli and Kevin Goess ported it to Perl.
My logging can be really simple. This short example loads
Log::Log4perl with the :easy import tag, which gives me $ERROR: a constant to denote the logging level,
and ERROR as the function to log
messages for that level. I use easy_init to set up the default logging by
telling it what sort of messages that I want to log, in this case those of
type $ERROR. After that, I can use
ERROR. Since I haven’t said anything
about where the logging output should go, Log::Log4perl
sends it to my terminal:
#!/usr/bin/perl # log4perl-easy1.pl use Log::Log4perl qw(:easy); Log::Log4perl->easy_init( $ERROR ); ERROR( "I've got something to say!" );
The error message I see on the screen has a date- and timestamp, as well as the message I sent:
2006/10/22 19:26:20 I've got something to say!
If I don’t want to go to the screen, I can give easy_init some extra information to let it know
what I want it to do. I use an anonymous hash to specify the level of
logging and the file I want it to go to. Since I want to append to my log,
I use a >> before the filename
just as I would with Perl’s open. This
example does the same thing as the previous one, save that its output goes
to error_log. In
Log::Log4perl parlance, I’ve configured an
appender:
#!/usr/bin/perl
# log4perl-easy2.pl
use Log::Log4perl qw(:easy);
Log::Log4perl->easy_init(
{
level => $ERROR,
file => ">> error_log",
}
);
ERROR( "I've got something to say!" );
I can change my program a bit. Perhaps I want to have some debugging
messages. I can use the DEBUG function
for those. When I set the target for the message, I use the special
filename STDERR, which stands in for
standard error:
#!/usr/bin/perl
# log4perl-easy3.pl
use strict;
use warnings;
use Log::Log4perl qw(:easy);
Log::Log4perl->easy_init(
{
file => ">> error_log",
level => $ERROR,
},
{
file => "STDERR",
level => $DEBUG,
}
);
ERROR( "I've got something to say!" );
DEBUG( "Hey! What's going on in there?" );
My error messages go to the file, and my debugging messages go to the standard error. However, I get both on the screen!
2006/10/22 20:02:45 I've got something to say! 2006/10/22 20:02:45 Hey! What's going on in there?
I don’t have to be content with simply logging messages, though. Instead of a string argument, I give the logging routines an anonymous subroutine to execute. This subroutine will run only when I’m logging at that level. I can do anything I like in the subroutine, and the return value becomes the log message:
#!/usr/bin/perl
# log4perl-runsub.pl
use strict;
use warnings;
use Log::Log4perl qw(:easy);
Log::Log4perl->easy_init(
{
file => "STDERR",
level => $DEBUG,
}
);
DEBUG( sub {
print "Here I was!"; # To STDOUT
return "I was debugging!" # the log message
} );
The messages are hierarchical; therefore configuring a message
level, such as $DEBUG, means that
messages for that level and all lower levels reach that appender.
Log::Log4perl defines five levels, where debugging is
the highest level (i.e., I get the most output from it). The DEBUG level gets the messages for all levels,
whereas the ERROR level gets the
messages for itself and FATAL. Here are
the levels and their hierarchy:
DEBUGINFOWARNERRORFATAL
Keep in mind, though, that I’m really configuring the appenders, all
of which get a chance to log the output. Each appender looks at the
message and figures out if it should log it. In the previous example, both
the error_log and STDERR appenders knew that they logged messages
at the ERROR level, so the ERROR messages showed up in both places. Only
the STDERR appender thinks it should
log messages at the DEBUG level, so the
DEBUG messages only show up on
screen.
The easy technique I used earlier defined a default logger that it secretly used.
For more control, I can create my own directly. In most applications,
this is what I’m going to do. This happens in two parts. First, I’ll
load Log::Log4perl and configure it. Second, I’ll get
a logger instance.
To load my own configuration, I replace my earlier call to
easy_init with init, which takes a filename argument. Once
I’ve initialized my logger, I still need to get an instance of the
logger (since I can have several instances going at the same time) by
calling get_logger. The easy_init method did this for me behind the
scenes, but now that I want more flexibility I have a bit more work to
do. I put my instance in $logger and
have to call the message methods such as error on that instance:
#!/usr/bin/perl # root-logger.pl use Log::Log4perl; Log::Log4perl::init( 'root-logger.conf' ); my $logger = Log::Log4perl->get_logger; $logger->error( "I've got something to say!" );
Now I have to configure Log::Log4perl. Instead
of easy_init making all of the
decisions for me, I do it myself. For now, I’m going to stick with a
single root logger. Log::Log4perl can have different
loggers in the same program, but I’m going to ignore those. Here’s a
simple configuration file that mimics what I was doing before, appending
messages at or below the ERROR level
to a file error_log:
# root-logger.conf log4perl.rootLogger = ERROR, myFILE log4perl.appender.myFILE = Log::Log4perl::Appender::File log4perl.appender.myFILE.filename = error_log log4perl.appender.myFILE.mode = append log4perl.appender.myFILE.layout = Log::Log4perl::Layout::PatternLayout log4perl.appender.myFILE.layout.ConversionPattern = [%c] (%F line %L) %m%n
The first line configures rootLogger. The first argument is the logging
level, and the second argument is the appender to use. I make up a name
that I want to use, and myFILE seems good
enough.
After I configure the logger, I configure the appender. Before I
start, there is no appender even though I’ve named one
(myFILE), and although I’ve given it a name,
nothing really happens. I have to tell Log4perl what myFile
should do.
First, I configure myFile to use
Log::Log4perl::Appender::File. I could use any of the
appenders that come with the module (and there are many), but I’ll keep
it simple. Since I want to send it to a file, I have to tell
Log::Log4perl::Appender::File which file to use and
which mode it should use. As with my easy example, I want to append to
error_log. I also have to tell it what to write to
the file.
I tell the appender to use
Log::Log4perl::Layout::PatternLayout so I can specify
my own format for the message, and since I want to use that, I need to
specify the pattern. The pattern string is similar to sprintf, but
Log::Log4perl takes care of the % placeholders for me. From the placeholders
in the documentation, I choose the pattern:
[%p] (%F line %L) %m%n
This pattern gives me an error message that includes the error
level (%p for priority), the filename
and line number that logged the message (%F and %L),
the message (%m), and finally a
newline (%n):
[ERROR] (root-logger.pl line 10) I've got something to say!
I have to remember that newline because the module doesn’t make any assumptions about what I’m doing with the message. There has been a recurring debate about this, and I think the module does it right: it does what I say rather than making me adapt to it. I just have to remember to add newlines myself, either in the format or in the messages (see Table 13-1).
Table 13-1. PatternLayout placeholders
Placeholder | Description |
|---|---|
| Category of the message |
| Package (class) name of the caller |
| Date-time as YYYY/MM/DD HH:MM:SS |
| Filename |
| Hostname |
| Shortcut for |
| Line number |
| The message |
| Method or function name |
| Newline |
| Priority (e.g., ERROR, DEBUG, INFO) |
| Process ID |
| Milliseconds since program start |
If I’m using this in a persistent program, such as something run under mod_perl,
I don’t need to load the configuration file every time. I can tell
Log::Log4perl not to reload it if it’s already done
it. The init_once method loads the
configuation one time only:
Log::Log4perl::init_once( 'logger.conf' );
Alternatively, I might want Log::Log4perl to
continually check the configuration file and reload it when it changes.
That way, by changing only the configuration file (remember that I
promised I could do this without changing the program), I can affect the
logging behavior while the program is still running. For instance, I
might want to crank up the logging level to see more messages (or send
them to different places). The second argument to init_and_watch is the refresh time, in
seconds:
Log::Log4perl::init_and_watch( 'logger.conf', 30 );
I’ve only shown the very basics of
Log::Log4perl. It’s much more powerful than that, and
there are already many excellent tutorials out there. Since
Log::Log4perl started life as Log4j, a Java library,
it maintains a lot of the same interface and configuration details, so
you might read the Log4j documentation or tutorials, too.
Having said that, I want to mention one last feature. Since
Log::Log4perl is written in Perl, I can use Perl
hooks in my configuration to dynamically affect the configuration. For
instance, Log::Log4perl::Appender::DBI sends messages
to a database, but I’ll usually need a username and password to write to
the database. I don’t want to store those in a file, so I grab them from
the environment. In this example of an appender, I pull that information
from %ENV. When
Log::Log4perl sees that I’ve wrapped a configuration
value in sub { }, it executes it
as Perl code:[49]
# dbi-logger.conf
log4perl.category = WARN, CSV
log4perl.appender.CSV = Log::Log4perl::Appender::DBI
log4perl.appender.CSV.datasource = DBI:CSV:f_dir=.
log4perl.appender.CSV.username = sub { $ENV{CSV_USERNAME} }
log4perl.appender.CSV.password = sub { $ENV{CSV_PASSWORD} }
log4perl.appender.CSV.sql = \
insert into csvdb \
(pid, level, file, line, message) values (?,?,?,?,?)
log4perl.appender.CSV.params.1 = %P
log4perl.appender.CSV.params.2 = %p
log4perl.appender.CSV.params.3 = %F
log4perl.appender.CSV.params.4 = %L
log4perl.appender.CSV.usePreparedStmt = 1
log4perl.appender.CSV.layout = Log::Log4perl::Layout::NoopLayout
log4perl.appender.CSV.warp_message = 0
My program to use this new logger is the same as before, although
I add some initialization in a BEGIN block to create
the database file if it isn’t already there:
#!/usr/bin/perl
# log4perl-dbi.pl
use Log::Log4perl;
Log::Log4perl::init( 'dbi-logger.conf' );
my $logger = Log::Log4perl->get_logger;
$logger->warn( "I've got something to say!" );
BEGIN {
# create the database if it doesn't already exist
unless( -e 'csvdb' )
{
use DBI;
$dbh = DBI->connect("DBI:CSV:f_dir=.")
or die "Cannot connect: " . $DBI::errstr;
$dbh->do(<<"HERE") or die "Cannot prepare: " . $dbh->errstr();
CREATE TABLE csvdb (
pid INTEGER,
level CHAR(64),
file CHAR(64),
line INTEGER,
message CHAR(64)
)
HERE
$dbh->disconnect();
}
}
I can do much more complex things with the Perl hooks available in the configuration files as long as I can write the code to do it.
I can easily add logging to my programs with
Log::Log4perl, a Perl version of the Log4j package. I
can use the easy configuration, or specify my own complex configuration.
Once configured, I call subroutines or methods to make a message available
to Log::Log4perl, which decides where to send the
message or if it should ignore it. I just have to send it the
message.
“The log4perl project” at Sourceforge (http://log4perl.sourceforge.net/)
has Log4perl FAQs, tutorials, and other support
resources for the package. You can find answers to most of the basic
questions about using the module, such as “How do I rotate logfiles
automatically?”
Michael Schilli wrote about Log4perl on Perl.com,
“Retire Your Debugger, Log Smartly with Log::Log4perl!” (http://www.perl.com/pub/a/2002/09/11/log4perl.html).
Log4Perl is closely related to Log4j (http://logging.apache.org/log4j/docs/),
the Java logging library, so you do things the same way in each. You can
find good tutorials and documentation for log4j here
that you might be able to apply to
Log4perl, too.
Get Mastering Perl now with the O’Reilly learning platform.
O’Reilly members experience books, live events, courses curated by job role, and more from O’Reilly and nearly 200 top publishers.
