O'Reilly logo

Mastering Perl by brian d foy

Stay ahead with the world's most comprehensive technology and business learning platform.

With Safari, you learn the way you learn best. Get unlimited access to videos, live online training, learning paths, books, tutorials, and more.

Start Free Trial

No credit card required

Chapter 13. Logging

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.

Recording Errors and Other Information

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.

Log4perl

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:

  • DEBUG

  • INFO

  • WARN

  • ERROR

  • FATAL

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.

Configuring Log4perl

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

%c

Category of the message

%C

Package (class) name of the caller

%d

Date-time as YYYY/MM/DD HH:MM:SS

%F

Filename

%H

Hostname

%l

Shortcut for %c %f (%L)

%L

Line number

%m

The message

%M

Method or function name

%n

Newline

%p

Priority (e.g., ERROR, DEBUG, INFO)

%P

Process ID

%r

Milliseconds since program start

Persistent Logging

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 );

Other Log::Log4perl Features

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.

Summary

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.

Further Reading

“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.



[48] Or even in a database if you have some custom logging stuff going on.

[49] If I don’t like that flexibility because I don’t trust the people with access to the configuration file, I can turn off the Perl hooks in the configuration with this line of code: Log::Log4perl::Config->allow_code(0);.

With Safari, you learn the way you learn best. Get unlimited access to videos, live online training, learning paths, books, interactive tutorials, and more.

Start Free Trial

No credit card required