perl-icon_aThis article contains eight (8) of my most frequently used Log::Log4perl recipes. 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

NOTE: 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.

Comments   

0 #20 Patrick Piper 2013-08-20 14:42
Quoting Brian:
Regarding Recipe 5: When I use recipe 5 to have multiple scripts write to the same log file, in conjunction with log rotation as you have described in recipe 7, the log files never seem to rotate, even when they reach or exceed the size limiter I have placed in the configuration file. I've included a size parameter for both LOG1 and LOG2.

Should I be doing something different?


It should be possible to combine recipe 5 and recipe 7. Two different scripts should be able to use Log::Dispatch:: FileRotate and have the log file rotate after x MB or so. Suggest that you examine the version of the module, perl, etc. and perhaps experiment by ensuring you're at the latest release(s).
Quote
0 #19 Brian 2013-08-13 07:20
Regarding Recipe 5: When I use recipe 5 to have multiple scripts write to the same log file, in conjunction with log rotation as you have described in recipe 7, the log files never seem to rotate, even when they reach or exceed the size limiter I have placed in the configuration file. I've included a size parameter for both LOG1 and LOG2.

Should I be doing something different?
Quote
0 #18 Amit Marathe 2013-07-29 10:13
Hi Patrick,
Thank you very much for sharing this really Helpful information on "log4perl" module.
Your documentation is really simple to understand & implements.
Thanks a ton...
Best Regards,
-- Amit.
Quote
0 #17 Patrick Piper 2012-09-24 18:29
Quoting ash:
Output messages to file and screen using appenders, can I only get info messages on screen


yes, you can using Filters.

Add the following to the original recipe #2 at the bottom

# Filter to match level INFO
log4perl.filter.MatchInfo = Log::Log4perl::Filter::LevelMatch
log4perl.filter.MatchInfo.LevelToMatch = INFO
log4perl.filter.MatchInfo.AcceptOnMatch = true

# Info appender
log4perl.appender.SCREEN.Filter = MatchInfo
Quote
0 #16 ash 2012-09-24 06:25
Output messages to file and screen using appenders, can I only get info messages on screen
Quote
0 #15 Meir 2012-03-07 11:52
Hmmm,

Good idea! I'll experiment with the log4perl anyway using your advice, but I'll also look up Time::Progress.
Quote
0 #14 Patrick Piper 2012-03-07 08:33
Quoting Meir:
Dear Patrick,
I read more than a dozen or so log4gerl docs, starting with "Retire your debugger, log smartly with Log::Log4perl!" by Michael Schilli, his PPT presentation, all the CPAN man pages, the FAQ and of course this very helpful blog page of yours.
There are a lot of examples telling you how to send the SAME log message to both screen and file. Yes, it is possible to specify different layouts/patterns and even filters and thresholds. Nice! But in all cases it is the SAME message that goes to both destinations.
But what I would like to do is as follows:
* Log to file full text messages as specified by level, category, etc.;
* Send to the screen a single dot, no CR and/or LF, for say every INFO message, but a full message for all WART and up message.
This way, one sees a "progression bar" of sort as long as everything is progressing nicely and a message when an exception happens.
Can this be done? How?
Thanks!


Yes, I think you could do it, but it seems more efficient to use something like Time::Progress for printing out a progress bar/meter, instead of having Log::Log4perl do that.

To get this to work you would need to use a regex filter to prevent '^\.$' from going to FILE, instead sending that to SCREEN. Additionally, the SCREEN channel would only output WARN and greater.

IMHO, I think the better way would be to use a real progress bar like Time::Progress.
Quote
0 #13 Meir 2012-03-07 03:56
Dear Patrick,
I read more than a dozen or so log4gerl docs, starting with "Retire your debugger, log smartly with Log::Log4perl!" by Michael Schilli, his PPT presentation, all the CPAN man pages, the FAQ and of course this very helpful blog page of yours.
There are a lot of examples telling you how to send the SAME log message to both screen and file. Yes, it is possible to specify different layouts/pattern s and even filters and thresholds. Nice! But in all cases it is the SAME message that goes to both destinations.
But what I would like to do is as follows:
* Log to file full text messages as specified by level, category, etc.;
* Send to the screen a single dot, no CR and/or LF, for say every INFO message, but a full message for all WART and up message.
This way, one sees a "progression bar" of sort as long as everything is progressing nicely and a message when an exception happens.
Can this be done? How?
Thanks!
Quote
0 #12 Sumit 2012-01-02 03:08
Thank you very much Patrick,

It worked out without any issues, just perfectly. :)

Thanks again.

Sumit.
Quote
+1 #11 Patrick Piper 2011-12-30 08:45
Quoting Sumit:
Thanks a lot......Really really very useful blog..

Can u help me with the following scenario:

I am saving Error+ logs into DB for certain events, having event_id as PK in table. Now I want to find a way to pass the Event id from my scripts to log4perl, i.e.

$logger->error($event_id, 'This is Error Message');

is that doable ?


Yes, that should be possible with minor changes to the above recipe. If you wanted to store an event_id in the log_id field, for example, you would simply do the following:

1- edit the log4perl sql statement

log4perl.append er.DBI.sql=INSE RT INTO log VALUES (?,?,?,?,?)

NOTE: the 0 was changed to a ?

2 - chagne the order of the DBI params in the log4perl.conf file

#1 = event_id
log4perl.append er.DBI.params.2 =%F{1}
log4perl.append er.DBI.params.3 =%d{YYYY-MM-DD HH:mm:ss}
log4perl.append er.DBI.params.4 =%p
#5 = message

3 - use the following log call

$log->info($eve nt_id, "This is my message");

That should work, give it a try!

Remember to ensure that log_id is NOT an AUTO INCREMENTING integer AND that there are no UNIQUE INDEX constraints on that column in the database.

Thanks
Quote

Add comment


Security code
Refresh