Chapter 13. Logging

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 only run 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(
    {
    level => $DEBUG,
    file  => "STDERR",
    }
    );

DEBUG( sub {
    print "Here I was!";      # To STDOUT
    return "I was debugging!" # the log message
    } );

I can also use a subroutine reference to avoid creating a large string argument. For instance, I might want to use Data::Dumper to show a big data structure. If I call Dumper in the argument list, Perl calls it, creates the big string, then uses that as the argument to DEBUG even before it knows if DEBUG will do anything:

use Data::Dumper;

# always calls Dumper()
DEBUG( Dumper( \%big_data_structure ) );

If I use a subroutine reference, <DEBUG> only runs the subroutine reference if it’s going to log the message:

DEBUG( sub { Dumper( \%big_data_structure ) } );

The “easy” technique I used earlier defined a default logger that it 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, 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 = [%p] (%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.

log4perl.appender.Screen.layout.ConversionPattern = [%x] %m%n

use Log::Log4perl;

Log::Log4perl->init( 'log4perl.conf' );

my $logger = Log::Log4perl->get_logger;
Log::Log4perl::NDC->push( 'Buster' );

$logger->info( 'info level' );

[Buster] info level

use Log::Log4perl;

Log::Log4perl->init( 'log4perl.conf' );

my $logger = Log::Log4perl->get_logger;
Log::Log4perl::NDC->push( 'Buster' );
Log::Log4perl::NDC->push( 'Mimi' );

[Buster Mimi] info level

log4perl.appender.Screen.layout.ConversionPattern = [%X{Cat}] %m%n

use Log::Log4perl;

Log::Log4perl->init( 'log4perl.conf' );

my $logger = Log::Log4perl->get_logger;
Log::Log4perl::MDC->put( 'Cat', 'Buster' );
Log::Log4perl::MDC->put( 'Dog', 'Droopy' );


$logger->info( 'info level' );

[Buster] info level

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 the configuration file, and the configuration file only (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 );

When I turn on logging, I don’t always want to turn it on for the entire program. Perhaps I need to pay attention to only one part of the program. Instead of using the rootLogger, I can define categories and configure them separately. A category is really a logger that’s confined to a particular component.

In the configuration file, I replace rootLogger with a name that I choose, and configure it as I did earlier. Different categories can share the same appender. In this example, I defined three categories, two of which share the CSV appender:

# category-logger.conf
log4perl.someCategory = WARN, CSV
log4perl.someOtherCategory = FATAL, CSV
log4perl.anotherCategory = INFO, DBI

...CSV appender config...

...DBI appender config...

In my program, I access these category loggers by specifiying their name in my call to get_logger:

my $someCategory = Log::Log4perl->get_logger( 'someCategory' );
$someCategory->debug( 'This is from someCategory' );

my $anotherCategory = Log::Log4perl->get_logger( 'anotherCategory' );
$anotherCategory->debug( 'This is from anotherCategory' );

I like to name my logging instance variables after the category name, and since the configuration file looks like Java (coming from log4j), some CamelCase sneaks into my program.

I like to create categories for each of the modules in my application. I can turn on logging per module. Log::Log4perl lets me use the :: as a separator in the configuration:

log4perl.My::Module = WARN, CSV
log4perl.Our::Module = FATAL, CSV
log4perl.Your::Module = INFO, DBI

The colons are the same as dots, so this configuration is the same:

log4perl.My.Module = WARN, CSV
log4perl.Our.Module = FATAL, CSV
log4perl.Your.Module = INFO, DBI

Inside my program, I can then get the module logger without explicitly stating the package name since I can use the __PACKAGE__ token:

my $logger = Log::Log4perl->get_logger( __PACKAGE__ );

log4perl.logger.Foo                  = DEBUG, FooScreen
log4perl.logger.Foo.Bar              = INFO, FooBarScreen

log4perl.appender.FooScreen  = Log::Log4perl::Appender::Screen
log4perl.appender.FooScreen.layout   = Log::Log4perl::Layout::PatternLayout
log4perl.appender.FooScreen.layout.ConversionPattern = FooScreen %c [%p] %m%n

log4perl.appender.FooBarScreen  = Log::Log4perl::Appender::Screen
log4perl.appender.FooBarScreen.layout   = Log::Log4perl::Layout::PatternLayout
log4perl.appender.FooBarScreen.layout.ConversionPattern = FooBarScreen %c [%p] %m%n

#!/usr/bin/perl
# hierarchial logging

my $file = 'categories.conf';

Log::Log4perl->init( $file );

my $foo = Log::Log4perl->get_logger( 'Foo' );
my $foo_bar = Log::Log4perl->get_logger( 'Foo::Bar' );

$foo->error( 'error from foo' );
$foo->warn( 'warn from foo' );
$foo->info( 'info from foo' );
$foo->debug( 'debug from foo' );
$foo->trace( 'trace from foo' );

$foo_bar->error( 'error from foo_bar' );
$foo_bar->warn( 'warn from foo_bar' );
$foo_bar->info( 'info from foo_bar' );
$foo_bar->debug( 'debug from foo_bar' );
$foo_bar->trace( 'trace from foo_bar' );

FooScreen Foo [ERROR] error from foo
FooScreen Foo [WARN] warn from foo
FooScreen Foo [INFO] info from foo
FooScreen Foo [DEBUG] debug from foo
FooBarScreen Foo.Bar [ERROR] error from foo_bar
FooScreen Foo.Bar [ERROR] error from foo_bar
FooBarScreen Foo.Bar [WARN] warn from foo_bar
FooScreen Foo.Bar [WARN] warn from foo_bar
FooBarScreen Foo.Bar [INFO] info from foo_bar
FooScreen Foo.Bar [INFO] info from foo_bar

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:

# dbi-logger.conf
log4perl.rootLogger = 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.