perl.com: Retire your debugger, log smartly with Log::Log4perl!

Retire your debugger, log smartly with Log::Log4perl!
by Michael Schilli | Pages: 1, 2, 3, 4

Typical Use Cases

The configuration file format is more compact than the Perl code, so let's use it to illustrate some real-world cases (although you could do the same things in Perl, of course!):

We've seen before that a configuration line like:

    log4perl.logger.Groceries=DEBUG, A1

will turn on logging in Groceries::Drink and Groceries::Food (and all of their descendants if they exist) with priority DEBUG via inheritance. What if Groceries::Drink gets a bit too noisy and you want to raise its priority to at least INFO while keeping the DEBUG setting for Groceries::Food? That's easy, no need to change your code, just modify the configuration file:

    log4perl.logger.Groceries.Drink=INFO, A1
    log4perl.logger.Groceries.Food=DEBUG, A1

or, you could use inheritance to accomplish the same thing. You define INFO as the priority for Groceries and override Groceries.Food with a less restrictive setting:

    log4perl.logger.Groceries=INFO, A1
    log4perl.logger.Groceries.Food=DEBUG, A1

Groceries::Food will be still on DEBUG after that, while Groceries and Groceries::Drinks will be on INFO.

Or, you could choose to turn on detailed DEBUG logging all over the system and just bump up the minimum level for the noisy Groceries.Drink:

    log4perl.logger=DEBUG, A1
    log4perl.logger.Groceries.Drink=INFO, A1

This sets the root logger to DEBUG, which all other loggers in the system will inherit. Except Groceries.Drink and its descendents, of course, which will carry the INFO priority.

Or, similarily to what we've talked about in the Beginner's Pitfalls section, let's say you wanted to print FATAL messages system-wide to STDOUT, while turning on detailed logging under Groceries::Food and writing the messages to a log file? Use this:

    log4perl.logger=FATAL, Screen
    log4perl.logger.Groceries.Food=DEBUG, Log
    
    log4perl.appender.Screen=Log::Dispatch::Screen
    log4perl.appender.Screen.stderr=0
    log4perl.appender.Screen.Threshold=FATAL
    log4perl.appender.Screen.layout=Log::Log4perl::Layout::SimpleLayout
    
    log4perl.appender.Log=Log::Dispatch::File
    log4perl.appender.Log.filename=test.log
    log4perl.appender.Log.mode=append
    log4perl.appender.Log.layout=Log::Log4perl::Layout::SimpleLayout

As mentioned in Appenders, setting the appender threshold of the screen appender to FATAL keeps DEBUG messages out of the root appender and so effectively prevents message duplication.

According to the Log::Dispatch::Screen documentation, setting its stderr attribute to a false value causes it log to STDOUT instead of STDERR. log4perl.appender.XXX.layout is the configuration file way to specify the no-frills Layout seen earlier.

You could also have multiple appenders attached to one category, like in

    log4perl.logger.Groceries=DEBUG, Log, Database, Emailer

if you had Log::Dispatch-type appenders defined for Log, Database and Emailer.

Performance Penalties and How to Minimize Them

Logging comes with a (small) price tag: We figure out at runtime if a message is going to be logged or not. Log::Log4perl's primary design directive has been to run this check at maximum speed in order to avoid slowing down the application. Internally, it has been highly optimized so that even if you're using large category hierarchies, the impact of a call to e.g. $logger->debug() in non-DEBUG mode is negligable.

While Log::Log4perl tries hard not to impose a runtime penalty on your application, it has no control over the code leading to Log::Log4perl calls and needs your cooperation with that. For example, take a look at this:

   use Data::Dumper;
   $log->debug("Dump: ", Dumper($resp));

Passing arguments to the logging functions can impose a severe runtime penalty, because there's often expensive operations going on before the arguments are actually passed on to Log::Log4perl's logging functions. The snippet above will have Data::Dumper completely unravel the structure of the object behind $resp, pass the whole slew on to debug(), which might then very well decide to throw it away. If the effective debug level for the current category isn't high enough to actually forward the message to the appropriate appender(s), then we should have never called Dumper() in the first place.

With this in mind, the logging functions don't only accept strings as arguments, but also subroutine references which, in case the logger is actually firing, it will call the subroutine behind the reference and take its output as a message:

   $log->debug("Dump: ", sub { Dumper($resp) } );

The snippet above won't call Dumper() right away, but pass on the subroutine reference to the logger's DEBUG method instead. Perl's closure mechanism will make sure that the value of $resp will be preserved, even if the subroutine will be handed over to Log::Log4perls lower level functions. Once Log::Log4perl will decide that the message is indeed going to be logged, it will execute the subroutine, take its return value as a string and log it.

Also, your application can help out and check if it's necessary to pass any parameters at all:

   if($log->is_debug()) {
       log->debug("Interpolation: @long_array");
   }

At the cost of a little code duplication, we avoid interpolating a huge array into the log string in case the effective log level prevents the message from being logged anyway.

Installation

Log::Log4perl is freely available from CPAN. It also requires the presence of two other modules, Log::Dispatch (2.00 or better, which is a bundle itself) and Time::HiRes (1.20 or better). If you're using the CPAN shell to install Log::Log4perl, then it will resolve these and other recursive dependencies for you automatically and download the required modules one by one from CPAN.

At the time this article went to print, 0.22 was the stable release of Log::Log4perl, available from [1] and CPAN. Also on [1], the CVS source tree is publicly available for those who want the (sometimes shaky) bleeding development edge. The CPAN releases, on the other hand are guaranteed to be stable.

If you have questions, requests for new features, or if you want to contribute a patch to Log::Log4perl, then please send them to our mailing list at log4perl-devel@lists.sourceforge.net on SourceForge.

Project Status and Similar Modules

Log::Log4perl has been inspired by Tatsuhiko Miyagawa's clever Log::Dispatch::Config module, which provides a wrapper around the Log::Dispatch bundle and understands a subset of the log4j configuration file syntax. However, Log::Dispatch::Config does not provide a full Perl API to log4j -- and this is a key issue which Log::Log4perl has been designed to address. Log::Log4perl is a log4j port, not just a subset.

The Log::Log4perl project is still under development, but its API has reached a fairly mature state, where we will change things only for (very) good reasons. There's still a few items on the to-do list, but these are mainly esoteric features of log4j that still need to find their way into Log::Log4perl, since the overall goal is to keep it compatible. Also, Log::Log4perl isn't thread safe yet -- but we're working on it.

Thanks

Special thanks go to fellow Log4perl founder Kevin Goess (cpan@goess.org), who wrote half of the code, helped generously to correct the manuscript for this article and invented these crazy performance improvements, making log4j jealous!

Mission

Scatter plenty of debug statements all over your code -- and put them to sleep via the Log::Log4perl configuration. Let the INFO, ERROR and FATAL statements print to a log file. If you run into trouble, then lower the level in selected parts of the system, and redirect the additional messages to a different file. The dormant DEBUG statements won't cost you anything -- but if you run into trouble, then they might save the day, because your system will have an embedded debugger on demand. Have fun!