Retire your debugger, log smartly with Log::Log4perl!

by Michael Schilli
September 11, 2002

You've rolled out an application and it produces mysterious, sporadic errors? That's pretty common, even if fairly well-tested applications are exposed to real-world data. How can you track down when and where exactly your problem occurs? What kind of user data is it caused by? A debugger won't help you there.

And you don't want to keep track of only bad cases. It's helpful to log all types of meaningful incidents while your system is running in production, in order to extract statistical data from your logs later. Or, what if a problem only happens after a certain sequence of 'good' cases? Especially in dynamic environments like the Web, anything can happen at any time and you want a footprint of every event later, when you're counting the corpses.

What you need is well-architected logging: Log statements in your code and a logging package like Log::Log4perl providing a "remote-control," which allows you to turn on previously inactive logging statements, increase or decrease their verbosity independently in different parts of the system, or turn them back off entirely. Certainly without touching your system's code -- and even without restarting it.

Related Reading Perl in a Nutshell By Stephen Spainhour, Ellen Siever, Nathan Patwardhan Table of Contents Index Sample Chapter Read Online--Safari Search this book on Safari:   Only This Book All of Safari Code Fragments only

However, with traditional logging systems, the amount of data written to the logs can be overwhelming. In fact, turning on low-level-logging on a system under heavy load can cause it to slow down to a crawl or even crash.

Log::Log4perl is different. It is a pure Perl port of the widely popular Apache/Jakarta log4j library [3] for Java, a project made public in 1999, which has been actively supported and enhanced by a team around head honcho Ceki Gülcü during the years.

The comforting facts about log4j are that it's really well thought out, it's the alternative logging standard for Java and it's been in use for years with numerous projects. If you don't like Java, then don't worry, you're not alone -- the Log::Log4perl authors (yours truly among them) are all Perl hardliners who made sure Log::Log4perl is real Perl.

In the spirit of log4j, Log::Log4perl addresses the shortcomings of typical ad-hoc or homegrown logging systems by providing three mechanisms to control the amount of data being logged and where it ends up at:

• Levels allow you to specify the priority of log messages. Low-priority messages are suppressed when the system's setting allows for only higher-priority messages.
• Categories define which parts of the system you want to enable logging in. Category inheritance allows you to elegantly reuse and override previously defined settings of different parts in the category hierarchy.
• Appenders allow you to choose which output devices the log data is being written to, once it clears the previously listed hurdles.

In combination, these three control mechanisms turn out to be very powerful. They allow you to control the logging behavior of even the most complex applications at a granular level. However, it takes time to get used to the concept, so let's start the easy way:

Getting Your Feet Wet With Log4perl

If you've used logging before, then you're probably familiar with logging priorities or levels . Each log incident is assigned a level. If this incident level is higher than the system's logging level setting (typically initialized at system startup), then the message is logged, otherwise it is suppressed.

Log::Log4perl defines five logging levels, listed here from low to high:

    DEBUG
    INFO
    WARN
    ERROR
    FATAL

Let's assume that you decide at system startup that only messages of level WARN and higher are supposed to make it through. If your code then contains a log statement with priority DEBUG, then it won't ever be executed. However, if you choose at some point to bump up the amount of detail, then you can just set your system's logging priority to DEBUG and you will see these DEBUG messages starting to show up in your logs, too.

Listing drink.pl shows an example. Log::Log4perl is called with the qw(:easy) target to provide a beginner's interface for us. We initialize the logging system with easy_init($ERROR), telling it to suppress all messages except those marked ERROR and higher (ERROR and FATAL that is). In easy mode, Log::Log4perl exports the scalars $DEBUG, $INFO etc. to allow the user to easily specify the desired priority.

Listing 1: drink.pl

    01 use Log::Log4perl qw(:easy);
    02 
    03 Log::Log4perl->easy_init($ERROR);
    04 
    05 drink();
    06 drink("Soda");
    07 
    08 sub drink {
    09     my($what) = @_;
    10 
    11     my $logger = get_logger();
    12 
    13     if(defined $what) {
    14         $logger->info("Drinking ", $what);
    15     } else {
    16         $logger->error("No drink defined");
    17     }
    18 }

drink.pl defines a function, drink(), which takes a beverage as an argument and complains if it didn't get one. In the Log::Log4perl world, logger objects do the work. They can be obtained by the get_logger() function, returning a reference to them.

There's no need to pass around logger references between your system's functions. This effectively avoids cluttering up your beautifully crafted functions/methods with parameters unrelated to your implementation. get_logger() can be called by every function/method directly with little overhead in order to obtain a logger. get_logger makes sure that no new object is created unnecessarily. In most cases, it will just cheaply return a reference to an already existing object (singleton mechanism).

The logger obtained by get_logger() (also exported by Log::Log4perl in :easy mode) can then be used to trigger logging incidents using the following methods, each taking one or more messages, which they just concatenate when it comes to printing them:

    $logger->debug($message, ...);
    $logger->info($message, ...);
    $logger->warn($message, ...);
    $logger->error($message, ...);
    $logger->fatal($message, ...);

The method names are corresponding with messages priorities: debug() logs with level DEBUG, info with INFO and so forth. You might think that five levels are not enough to effectively block the clutter and let through what you actually need. But before screaming for more, read on. Log::Log4perl has different, more powerful mechanisms to control the amount of output you're generating.

drink.pl uses $logger->error() to log an error if a parameter is missing and $logger->info() to tell what it's doing in case everything's OK. In :easy mode, log messages are just written to STDERR, so the output we'll see from drink.pl will be:

    2002/08/04 11:43:09 ERROR> drink.pl:16 main::drink - No drink defined

Along with the current date and time, this informs us that in line 16 of drink.pl, inside the function main::drink(), a message of priority ERROR was submitted to the log system. Why isn't there a another message for the second call to drink(), which provides the beverage as required? Right, we've set the system's logging priority to ERROR, so INFO-messages are being suppressed. Let's correct that and change line 3 in drink.pl to:

    Log::Log4perl->easy_init($INFO);

This time, both messages make it through:

    2002/08/04 11:44:59 ERROR> drink.pl:14 main::drink - No drink defined
    2002/08/04 11:44:59 INFO> drink.pl:16 main::drink - Drinking Soda

Also, please note that the info() function was called with two arguments but just concatenated them to form a single message string.

Moving On to the Big Leagues

The :easy target brings beginners up to speed with Log::Log4perl quickly. But what if you don't want to log your messages solely to STDERR, but to a logfile, to a database or simply STDOUT instead? Or, if you'd like to enable or disable logging in certain parts of your system independently? Let's talk about categories and appenders for a second.

Pages: 1, 2, 3, 4

Next Page