8 Useful Log::Log4perl Recipes

/ Perl, Logging, Development

Perl Programming Language Logo

Eight (8) Log::Log4perl recipes that can be used to enhance debugging, reporting and visibility of your Perl scripts.

The Log::Log4perl is a Perl logging API port of the Log4J Java logging API. It's very comprehensive and is used in a large number of the scripts, tools, and applications that have been developed by Netlinx, Inc. In this article, we provide recipes for the following:

  1. Initializing Log4perl with a config file vs in-line
  2. Output messages to file and screen using appenders
  3. Log events and messages to a database
  4. Logging messages to Syslog
  5. Have different applications log to the same file
  6. Outputting stacktrace in logging messages
  7. Implementing rotating log files
  8. Applying log filtering

1 - Initializing Log4perl with a config file vs in-line

You have the choice of initializing the Log::Log4perl API framework using either a configuration file or via in-line code. This recipe shows you how to do both.

Solution

When initializing Log4perl with a configuration file, you will need to create a conf file with the necessary configuration directives as follows:

###############################################################################
#                              Log::Log4perl Conf                             #
###############################################################################
log4perl.rootLogger              = DEBUG, LOG1
log4perl.appender.LOG1           = Log::Log4perl::Appender::File
log4perl.appender.LOG1.filename  = /var/log/mylog.log
log4perl.appender.LOG1.mode      = append
log4perl.appender.LOG1.layout    = Log::Log4perl::Layout::PatternLayout
log4perl.appender.LOG1.layout.ConversionPattern = %d %p %m %n

The sample configuration file above might be named log4perl.conf. To initialize Log4perl using this configuration file, you would supply a string or variable representation of the path to the config file as follows:

#!/usr/bin/perl

use Log::Log4perl;

# Initialize Logger
my $log_conf = "/etc/log4perl.conf";
Log::Log4perl::init($log_conf);
my $logger = Log::Log4perl->get_logger();

# sample logging statement
$logger->info("this is an info log message");

Alternatively, you can initialize Log4perl without using a config file at all. It just means that the same directives used in the config file, must now be entered directly into our Perl script as in-line code. This is done as follows:

#!/usr/bin/perl
use Log::Log4perl;

# Initialize Logger
my $log_conf = q(
   log4perl.rootLogger              = DEBUG, LOG1
   log4perl.appender.LOG1           = Log::Log4perl::Appender::File
   log4perl.appender.LOG1.filename  = /var/log/mylog.log
   log4perl.appender.LOG1.mode      = append
   log4perl.appender.LOG1.layout    = Log::Log4perl::Layout::PatternLayout
   log4perl.appender.LOG1.layout.ConversionPattern = %d %p %m %n
);
Log::Log4perl::init(\$log_conf);
my $logger = Log::Log4perl->get_logger();

# sample logging statement
$logger->info("this is an info log message");

Discussion

Both of these two methods are certainly viable means for initializing Log::Log4perl. There are pros and cons for each method. Here are a few points that come to mind:

  • log4perl.conf files are not a good solution if you have to embed database credentials for Appender::DBI logging
  • log4perl.conf files don't scale well for many different scripts and unrelated utilities. A Perl-based application with a collection of related scripts and/or modules may make good use of the log4perl.conf method of initialization.
  • The In-line method of initializing Log::Log4perl offers more flexibility and is a better solution for standalone one-off Perl scripts/tools.
  • A large collection of unrelated Perl scripts using the same log4perl.conf file will surely make that file harder to maintain and will be more complex. There would be greater risk that you would clobber files.

2 - Output messages to file and screen using appenders

Solution

To log messages to both a file and to the console, you need to use the Log::Log4perl::Appender class to setup a File and Screen appender as follows:

###############################################################################
#                              Log::Log4perl Conf                             #
###############################################################################
log4perl.rootLogger              = DEBUG, LOG1, SCREEN
log4perl.appender.SCREEN         = Log::Log4perl::Appender::Screen
log4perl.appender.SCREEN.stderr  = 0
log4perl.appender.SCREEN.layout  = Log::Log4perl::Layout::PatternLayout
log4perl.appender.SCREEN.layout.ConversionPattern = %m %n
log4perl.appender.LOG1           = Log::Log4perl::Appender::File
log4perl.appender.LOG1.filename  = /var/log/mylog.log
log4perl.appender.LOG1.mode      = append
log4perl.appender.LOG1.layout    = Log::Log4perl::Layout::PatternLayout
log4perl.appender.LOG1.layout.ConversionPattern = %d %p %m %n

The configuration above will initialize the logger to pass the same logged messages to /var/log/mylog.log and to the console as STDOUT.

Discussion

This recipe can come in handy if you need to have log messages output to a log file, as well as, to STDOUT so that the screen output can be piped our captured by another calling script. Suppose we have a Perl script called 'get-perl-output.pl' that performs some routine and has a logger configured with Appenders to file and screen, it might look something like:

#!/usr/bin/perl
use Log::Log4perl;

# Initialize Logger
my $log_conf = "/etc/log4perl.conf";
Log::Log4perl::init($log_conf);
my $logger = Log::Log4perl->get_logger();

system('named-checkzone example.com db.example.com');
if( $? > 0 ) {
    $logger->error("there was an error in db.example.com");
}

Since this script will log to a file AND to STDOUT, we can capture its output by calling it from a different script to check for any messages with a priority of 'ERROR'. This can be done as follows:

#!/usr/bin/perl
my @output = `get-perl-output.pl`;

foreach my $line (@output) {
    chomp;
    if($line =~ m/ERROR/i) {
        # do something b/c we found an error
    }
}

It should be noted, that the output to STDOUT is buffered and there is apparently no way of enabling autoflush so that it doesn't buffer the output.

We felt this recipe deserved mentioning because of the need for scripts to call other scripts, and be able to react to certain messages that were output from the called scripts. This is a handy recipe for setting up two (2) appenders, one to file and the other to screen for this very reason. Some scripts and tools that perform work need to provide visual feedback to the user as well, while persisting all logged events to a log file for audit, review, and reporting purposes.

3 - Log events and messages to a database

Solution

This recipe is geared to showing you how to persist logged messages to a database instead of a file on the filesystem. This solution requires you to add DBI and an associated DBI database driver from CPAN. In this example, MySQL is used. Create your log4perl.conf as shown below:

############################################################
# A simple root logger with a Log::Log4perl::Appender::DBI #
############################################################
log4perl.rootLogger   = INFO, DBI
log4perl.appender.DBI = Log::Log4perl::Appender::DBI
log4perl.appender.DBI.datasource=DBI:mysql:database=test;host=localhost;port=3306
log4perl.appender.DBI.username=guest
log4perl.appender.DBI.password=12345
log4perl.appender.DBI.sql=INSERT INTO log VALUES (0,?,?,?,?)
log4perl.appender.DBI.params.1=%F{1}
log4perl.appender.DBI.params.2=%d{yyyy-MM-dd HH:mm:ss}
log4perl.appender.DBI.params.3=%p
log4perl.appender.DBI.usePreparedStmt=1
log4perl.appender.DBI.layout=Log::Log4perl::Layout::NoopLayout
log4perl.appender.DBI.warp_message=0

Before you can start creating a logger to use this database facility, you must create your log database table. The following is an example of how to create a basic log database table named 'log':

--
-- Definition of table `log`
--
DROP TABLE IF EXISTS `log`;
CREATE TABLE `log` (
  `log_id` int(11) NOT NULL auto_increment,
  `log_source` varchar(100) NOT NULL default '',
  `log_date` datetime NOT NULL default '0000-00-00 00:00:00',
  `log_level` varchar(10) NOT NULL default '',
  `log_mesg` varchar(200) NOT NULL default '',
  PRIMARY KEY  (`log_id`),
  KEY `log_date_idx` (`log_date`),
  KEY `log_source_idx` (`log_source`),
  KEY `log_mesg_idx` (`log_mesg`)
) ENGINE=MyISAM DEFAULT CHARSET=latin1;

Assuming that you have correctly installed all the necessary dependencies from CPAN, you should have messages in the log database table. You can check by issuing the following query in SQL:

SELECT * FROM mydb.log

This should reveal all logged messages from your 'log' database table. This method of persisting data is great for audit and compliance within large enterprise environments. The data stored in the database can be queried and presented to web pages, text-based reports, and/or spreadsheets.

4 - Logging messages to Syslog

Solution

Log::Log4perl can be used by Perl scripts or tools that need to write log messages to Syslog through the use of a special appender. This facility is provided in Log::Log4perl via the JavaMap::SyslogAppender which is a wrapper for the Log::Dispatch::Syslog module. To get this to work, you will need to install both Log::Log4perl, as well as, Log::Dispatch::Syslog. Our solution calls for a log4perl.conf file that would look like this:

############################################################
# A simple root logger using Log::Log4perl::JavaMap        #
############################################################
log4j.appender.SyslogAppender            = org.apache.log4j.SyslogAppender
log4j.appender.SyslogAppender.SyslogHost = localhost
log4j.appender.SyslogAppender.Facility   = daemon
log4j.appender.SyslogAppender.layout     = org.apache.log4j.PatternLayout
log4j.appender.SyslogAppender.ConversionPattern = %p: %m%n

Alternatively, you can always call the Log::Dispatch::Syslog code directly as follows:

############################################################
#  Log::Log4perl conf - Syslog                             #
############################################################
log4perl.rootLogger                = DEBUG, SYSLOG
log4perl.appender.SYSLOG           = Log::Dispatch::Syslog
log4perl.appender.SYSLOG.min_level = debug
log4perl.appender.SYSLOG.ident     = myprocess
log4perl.appender.SYSLOG.facility  = daemon
log4perl.appender.SYSLOG.layout    = Log::Log4perl::Layout::SimpleLayout

The Perl script which initializes the logger would need to minimally include the following:

#!/usr/bin/perl
use Log::Log4perl;

# Initialize Logger
my $log_conf = "/etc/log4perl.conf";
Log::Log4perl::init($log_conf);
my $logger = Log::Log4perl->get_logger();

# sample logging statement
$logger->info("this is an info log message");

Discussion

This recipe is used whenever you need to combine your logging information from Perl scripts, daemons, tools and applications with the messages that are collected by the system's Syslog facility.  This gives you the ability to "merge" your logged events with the rest of the system's events.  You may have this need for Auditing and Compliance reasons, or for historical persistence, or perhaps because Syslog events are later parsed for SNMP alert conditions for issuing traps.  You can combine this recipe with a generic Log::Log4perl::Appender::File if you want to send to both Syslog and a file of your choosing.

Should you have the need to write a Perl application that is "portable" between Unix and Windows operating systems, you have the option of utilizing another appender for the Syslog equivalent on the Windows platform.  You can use Log::Log4perl::JavaMap::NTEventLogAppender which wraps Log::Dispatch::Win32EventLog.

5 - Have different applications or scripts write to the same log file

Solution

The solution to this is to create separate loggers with different file appenders, but have them write to the same file name. A log4perl.conf file might look like this:

###############################################################################
#                              Log::Log4perl Conf                             #
###############################################################################
log4perl.logger.my_app           = DEBUG, LOG1
log4perl.appender.LOG1           = Log::Log4perl::Appender::File
log4perl.appender.LOG1.filename  = /var/log/mylog.log
log4perl.appender.LOG1.mode      = append
log4perl.appender.LOG1.layout    = Log::Log4perl::Layout::PatternLayout
log4perl.appender.LOG1.layout.ConversionPattern = %d %p %m %n

# second logger points to the same file but with different level
log4perl.logger.my_other_app     = INFO, LOG2
log4perl.appender.LOG2           = Log::Log4perl::Appender::File
log4perl.appender.LOG2.filename  = /var/log/mylog.log
log4perl.appender.LOG2.mode      = append
log4perl.appender.LOG2.layout    = Log::Log4perl::Layout::PatternLayout
log4perl.appender.LOG2.layout.ConversionPattern = %d %p %m %n

WARNING! It is very important that the mode of both file appenders be set to 'append' mode. Otherwise, the log file will get clobbered when both scripts try to write to the same log file.

To utilize this configuration, suppose we have to separate Perl scripts named my_app.pl and my_other_app.pl. They would both initialize the Log::Log4perl using the same conf file. Immediately after instantiating the $logger object, the get_logger() method would be called by each script, passing in the value of the logger to get, as follows:

#!/usr/bin/perl

use Log::Log4perl;

# Initialize Logger
my $log_conf = "/etc/log4perl.conf";
Log::Log4perl::init($log_conf);
my $logger = Log::Log4perl->get_logger('my_app');

# sample logging statement
$logger->info("this is an info log message");

NOTE: the my_app.pl shown above would get it's own logger "my_app" which corresponds to LOG1 and would log at the debug level and above. Our other script my_other_app.pl would look basically the same, with the exception of the call to get_log() function. It would call that method on the logger as follows:

$logger->get_logger('my_other_app');

Discussion

This recipe is for those times that you have a collection of related scripts and/or tools that make up a Perl application, and you want all messages logged by each component of the application to be logged to the same file, but possibly with different logging levels.

6 - Output stacktraces in your logging messages

Solution

You can add full stacktraces to logged messages by using Carp and Log::Log4perl together. This gives you the ability to issue logcarp and logcroak methods to the $logger object as follows:

#!/usr/bin/perl

use Carp;
use Log::Log4perl;

# Initialize Logger
my $log_conf = "/etc/log4perl.conf";
Log::Log4perl::init($log_conf);
my $logger = Log::Log4perl->get_logger();

# sample logging statement
$logger->logcarp("this is a warn log message w/ level 1 stacktrace");
$logger->logcluck("this is a warn log message w/ full stacktrace");
$logger->logcroak("dies w/ level 1 stacktrace");
$logger->logconfess("dies w/ full stacktrace");

The code above is hypothetical code, because not all of it would run. The last line using the logconfess method would never be reached because the logcroak method would be called first and exit the script with level 1 stacktrace.  The "use Carp;" statement is optional, but it's included for self-documenting purposes, and it may be used elsewhere in the code.

Discussion

Frequently when you start writing Perl scripts that require a logger, you will need to insert debugging statements to ascertain problem areas of the code during testing. Using the logcarp, logcluck, logcroak, and logconfess methods will help you imeasurably by returning level 1 and/or full stacktraces when error conditions are encountered in the code. The stacktrace output will provide you the exact line number of where the problem occurred.

7 - Implementing rotating log files

Solution

Whenever a file log appender is used, there is the risk that the log will continue to grow quite large and eventually deplete disk space, rendering a partition inaccessible. Log::Log4perl has an appender that can implement log rotation using a particular max file size, and save multiple versions of the log. To use FileRotate, you must download and install both Log::Log4perl and Log::Dispatch::FileRotate from CPAN. A log4perl.conf file using log rotation would look like this:

###############################################################################
#                              Log::Log4perl Conf                             #
###############################################################################
log4perl.rootLogger              = DEBUG, LOG1
log4perl.appender.LOG1           = Log::Dispatch::FileRotate
log4perl.appender.LOG1.filename  = /var/log/mylog.log
log4perl.appender.LOG1.mode      = append
log4perl.appender.LOG1.autoflush = 1
log4perl.appender.LOG1.size      = 10485760
log4perl.appender.LOG1.max       = 5
log4perl.appender.LOG1.layout    = Log::Log4perl::Layout::PatternLayout
log4perl.appender.LOG1.layout.ConversionPattern = %d %p %m %n

Discussion

The log4perl.conf file above implements the Log::Dispatch::FileRotate appender directly. It would log all messages to /var/log/mylog.log. The mylog.log file would grow to a size of 10MB and it would be "rolled". A log file is rolled, by saving off a version of the current log file to a similarly named file with a version number at the end. In this example above, there would be up to 5 versions saved. It would look like this:

/var/log/mylog.log
/var/log/mylog.log.1
/var/log/mylog.log.2
/var/log/mylog.log.3
/var/log/mylog.log.4
/var/log/mylog.log.5

There would be 5 copies of the rolled log, each approximately 10MB in size. So, to calculate how much logging data you might save, you would multiple the size x max, in this case 10MB x 5 = 50MB would be the storage requirements for our logger.

8 - Apply log filters

Solution

Sometimes it's desirable to allow a certain logging level, but you want to ONLY show select messages based upon some REGEXP or pattern. You can do this easily in Log::Log4perl using output filtering. This recipe shows how to set logging messages to info, but only show messages with the word "SUCCESS" and/or "FAILURE" in them. Your log4perl.conf would look like this:

###############################################################################
#                              Log::Log4perl Conf                             #
###############################################################################
log4perl.rootLogger              = INFO, LOG1
log4perl.appender.LOG1           = Log::Log4perl::Appender::File
log4perl.filter.Filter1          = sub { /SUCCESS/ }
log4perl.filter.Filter2          = sub { /FAILURE/ }
log4perl.filter.FilterRule       = Log::Log4perl::Filter::Boolean
log4perl.filter.FilterRule.logic = Filter1 || Filter2
log4perl.appender.LOG1.Filter    = FilterRule
log4perl.appender.LOG1.filename  = /var/log/mylog.log
log4perl.appender.LOG1.mode      = append
log4perl.appender.LOG1.layout    = Log::Log4perl::Layout::PatternLayout
log4perl.appender.LOG1.layout.ConversionPattern = %d %p %m %n

Discussion

This recipe is most useful when you have a set logging level and you want to filter out most but not all the logged events without having to go back to the code and revise logging levels of statements. Our example above shows how you would filter out all messages at info or above unless they contained the string "SUCCESS" or "FAILURE" in the message text.

Next Post Previous Post