SEARCH
NEW RPMS
DIRECTORIES
ABOUT
FAQ
VARIOUS
BLOG
DONATE


YUM REPOSITORY

 
 

MAN page from RedHat EL 8 perl-Log-Log4perl-1.50-1.el8.noarch.rpm

FAQ

Section: User Contributed Perl Documentation (3)
Updated: 2020-07-22
Index 

NAME

Log::Log4perl::FAQ - Frequently Asked Questions on Log::Log4perl 

DESCRIPTION

This FAQ shows a wide variety ofcommonly encountered logging tasks and how to solve themin the most elegant way with Log::Log4perl. Most of the time, this willbe just a matter of smartly configuring your Log::Log4perl configuration files. 

Why use Log::Log4perl instead of any other logging module on CPAN?

That's a good question. There's dozens of logging modules on CPAN.When it comes to logging, people typically think: ``Aha. Writing outdebug and error messages. Debug is lower than error. Easy. I'm gonnawrite my own.'' Writing a logging module is like a rite of passage forevery Perl programmer, just like writing your own templating system.

Of course, after getting the basics right, features need tobe added. You'd like to write a timestamp with every message. Thentimestamps with microseconds. Then messages need to be written to boththe screen and a log file.

And, as your application grows in size you might wonder: Why doesn'tmy logging system scale along with it? You would like to switch onlogging in selected parts of the application, and not all across theboard, because this kills performance. This is when people turn toLog::Log4perl, because it handles all of that.

Avoid this costly switch.

Use "Log::Log4perl" right from the start. "Log::Log4perl"'s ":easy"mode supports easy logging in simple scripts:

    use Log::Log4perl qw(:easy);    Log::Log4perl->easy_init($DEBUG);    DEBUG "A low-level message";    ERROR "Won't make it until level gets increased to ERROR";

And when your application inevitably grows, your logging system growswith it without you having to change any code.

Please, don't re-invent logging. "Log::Log4perl" is here, it's easyto use, it scales, and covers many areas you haven't thought of yet,but will enter soon. 

What's the easiest way to use Log4perl?

If you just want to get all the comfort of logging, without muchoverhead, use Stealth Loggers. If you use Log::Log4perl in":easy" mode like

    use Log::Log4perl qw(:easy);

you'll have the following functions available in the current package:

    DEBUG("message");    INFO("message");    WARN("message");    ERROR("message");    FATAL("message");

Just make sure that every package of your code where you're using them inpulls in "use Log::Log4perl qw(:easy)" first, then you're set.Every stealth logger's category will be equivalent to the name of thepackage it's located in.

These stealth loggerswill be absolutely silent until you initialize Log::Log4perl inyour main program with either

        # Define any Log4perl behavior    Log::Log4perl->init("foo.conf");

(using a full-blown Log4perl config file) or the super-easy method

        # Just log to STDERR    Log::Log4perl->easy_init($DEBUG);

or the parameter-style method with a complexity somewhat in between:

        # Append to a log file    Log::Log4perl->easy_init( { level   => $DEBUG,                                file    => ">>test.log" } );

For more info, please check out ``Stealth Loggers'' in Log::Log4perl. 

How can I simply log all my ERROR messages to a file?

After pulling in the "Log::Log4perl" module, just initialize itsbehavior by passing in a configuration to its "init" method as a stringreference. Then, obtain a logger instance and write out a messagewith its "error()" method:

    use Log::Log4perl qw(get_logger);        # Define configuration    my $conf = q(        log4perl.logger                    = ERROR, FileApp        log4perl.appender.FileApp          = Log::Log4perl::Appender::File        log4perl.appender.FileApp.filename = test.log        log4perl.appender.FileApp.layout   = PatternLayout        log4perl.appender.FileApp.layout.ConversionPattern = %d> %m%n    );        # Initialize logging behavior    Log::Log4perl->init( \$conf );        # Obtain a logger instance    my $logger = get_logger("Bar::Twix");    $logger->error("Oh my, a dreadful error!");    $logger->warn("Oh my, a dreadful warning!");

This will append something like

    2002/10/29 20:11:55> Oh my, a dreadful error!

to the log file "test.log". How does this all work?

While the Log::Log4perl "init()" method typicallytakes the name of a configuration file as its input parameter likein

    Log::Log4perl->init( "/path/mylog.conf" );

the example above shows how to pass in a configuration as text in ascalar reference.

The configuration as showndefines a logger of the root category, which has an appender of type"Log::Log4perl::Appender::File" attached. The line

    log4perl.logger = ERROR, FileApp

doesn't list a category, defining a root logger. Compare that with

    log4perl.logger.Bar.Twix = ERROR, FileApp

which would define a logger for the category "Bar::Twix",showing probably different behavior. "FileApp" onthe right side of the assignment isan arbitrarily defined variable name, which is only used to somehowreference an appender defined later on.

Appender settings in the configuration are defined as follows:

    log4perl.appender.FileApp          = Log::Log4perl::Appender::File    log4perl.appender.FileApp.filename = test.log

It selects the file appender of the "Log::Log4perl::Appender"hierarchy, which will append to the file "test.log" if it alreadyexists. If we wanted to overwrite a potentially existing file, we wouldhave to explicitly set the appropriate "Log::Log4perl::Appender::File"parameter "mode":

    log4perl.appender.FileApp          = Log::Log4perl::Appender::File    log4perl.appender.FileApp.filename = test.log    log4perl.appender.FileApp.mode     = write

Also, the configuration defines a PatternLayout format, addingthe nicely formatted current date and time, an arrow (>) anda space before the messages, which is then followed by a newline:

    log4perl.appender.FileApp.layout   = PatternLayout    log4perl.appender.FileApp.layout.ConversionPattern = %d> %m%n

Obtaining a logger instance and actually logging something is typicallydone in a different system part as the Log::Log4perl initialisation section,but in this example, it's just done right after init for thesake of compactness:

        # Obtain a logger instance    my $logger = get_logger("Bar::Twix");    $logger->error("Oh my, a dreadful error!");

This retrieves an instance of the logger of the category "Bar::Twix",which, as all other categories, inherits behavior from the root logger if noother loggers are defined in the initialization section.

The "error()"method fires up a message, which the root logger catches. Itspriority is equal toor higher than the root logger's priority (ERROR), which causes the root loggerto forward it to its attached appender. By contrast, the following

    $logger->warn("Oh my, a dreadful warning!");

doesn't make it through, because the root logger sports a higher setting(ERROR and up) than the WARN priority of the message. 

How can I install Log::Log4perl on Microsoft Windows?

You can install Log::Log4perl using the CPAN client.

Alternatively you can install it using

    ppm install Log-Log4perl

if you're using ActiveState perl.

That's it! Afterwards, just create a Perl script like

    use Log::Log4perl qw(:easy);    Log::Log4perl->easy_init($DEBUG);    my $logger = get_logger("Twix::Bar");    $logger->debug("Watch me!");

and run it. It should print something like

    2002/11/06 01:22:05 Watch me!

If you find that something doesn't work, please let us know atlog4perl-develAATTlists.sourceforge.net --- we'll appreciate it. Have fun! 

How can I include global (thread-specific) data in my log messages?

Say, you're writing a web application and want all yourlog messages to include the current client's IP address. Most certainly,you don't want to include it in each and every log message like in

    $logger->debug( $r->connection->remote_ip,                    " Retrieving user data from DB" );

do you? Instead, you want to set it in a global data structure andhave Log::Log4perl include it automatically via a PatternLayout settingin the configuration file:

    log4perl.appender.FileApp.layout.ConversionPattern = %X{ip} %m%n

The conversion specifier %X{ip} references an entry under the key"ip" in the global "MDC" (mapped diagnostic context) table, whichyou've set once via

    Log::Log4perl::MDC->put("ip", $r->connection->remote_ip);

at the start of the request handler. Note that this is astatic (class) method, there's no logger object involved.You can use this method with as many key/value pairs as you like as longas you reference them under different names.

The mappings are stored in a global hash table within Log::Log4perl.Luckily, because the threadmodel in 5.8.0 doesn't share global variables between threads unlessthey're explicitly marked as such, there's no problem with multi-threadedenvironments.

For more details on the MDC, please refer to``Mapped Diagnostic Context (MDC)'' in Log::Log4perl andLog::Log4perl::MDC. 

My application is already logging to a file. How can I duplicate all messages to also go to the screen?

Assuming that you already have a Log4perl configuration file like

    log4perl.logger                    = DEBUG, FileApp    log4perl.appender.FileApp          = Log::Log4perl::Appender::File    log4perl.appender.FileApp.filename = test.log    log4perl.appender.FileApp.layout   = PatternLayout    log4perl.appender.FileApp.layout.ConversionPattern = %d> %m%n

and log statements all over your code,it's very easy with Log4perl to have the same messages both printed tothe logfile and the screen. No reason to change your code, of course,just add another appender to the configuration file and you're done:

    log4perl.logger                    = DEBUG, FileApp, ScreenApp    log4perl.appender.FileApp          = Log::Log4perl::Appender::File    log4perl.appender.FileApp.filename = test.log    log4perl.appender.FileApp.layout   = PatternLayout    log4perl.appender.FileApp.layout.ConversionPattern = %d> %m%n    log4perl.appender.ScreenApp          = Log::Log4perl::Appender::Screen    log4perl.appender.ScreenApp.stderr   = 0    log4perl.appender.ScreenApp.layout   = PatternLayout    log4perl.appender.ScreenApp.layout.ConversionPattern = %d> %m%n

The configuration file above is assuming that both appenders areactive in the same logger hierarchy, in this case the "root" category.But even if you've got file loggers defined in several parts of your system,belonging to different logger categories,each logging to different files, you can gobble up all logged messagesby defining a root logger with a screen appender, which would duplicatemessages from all your file loggers to the screen due to Log4perl'sappender inheritance. Check

    http://www.perl.com/pub/a/2002/09/11/log4perl.html

for details. Have fun! 

How can I make sure my application logs a message when it dies unexpectedly?

Whenever you encounter a fatal error in your application, instead of sayingsomething like

    open FILE, "<blah" or die "Can't open blah -- bailing out!";

just use Log::Log4perl's fatal functions instead:

    my $log = get_logger("Some::Package");    open FILE, "<blah" or $log->logdie("Can't open blah -- bailing out!");

This will both log the message with priority FATAL according to your currentLog::Log4perl configuration and then call Perl's "die()"afterwards to terminate the program. It works the same withstealth loggers (see ``Stealth Loggers'' in Log::Log4perl),all you need to do is call

    use Log::Log4perl qw(:easy);    open FILE, "<blah" or LOGDIE "Can't open blah -- bailing out!";

What can you do if you're using some library which doesn't use Log::Log4perland calls "die()" internally if something goes wrong? Use a$SIG{__DIE__} pseudo signal handler

    use Log::Log4perl qw(get_logger);    $SIG{__DIE__} = sub {        if($^S) {            # We're in an eval {} and don't want log            # this message but catch it later            return;        }        local $Log::Log4perl::caller_depth =              $Log::Log4perl::caller_depth + 1;        my $logger = get_logger("");        $logger->fatal(@_);        die @_; # Now terminate really    };

This will catch every "die()"-Exception of yourapplication or the modules it uses. In case you want toItwill fetch a root logger and pass on the "die()"-Message to it.If you make sure you've configured with a root logger like this:

    Log::Log4perl->init(\q{        log4perl.category         = FATAL, Logfile        log4perl.appender.Logfile = Log::Log4perl::Appender::File        log4perl.appender.Logfile.filename = fatal_errors.log        log4perl.appender.Logfile.layout = \                   Log::Log4perl::Layout::PatternLayout        log4perl.appender.Logfile.layout.ConversionPattern = %F{1}-%L (%M)> %m%n    });

then all "die()" messages will be routed to a file properly. The line

     local $Log::Log4perl::caller_depth =           $Log::Log4perl::caller_depth + 1;

in the pseudo signal handler above merits a more detailed explanation. Withthe setup above, if a module calls "die()" in one of its functions,the fatal message will be logged in the signal handler and not in theoriginal function --- which will cause the %F, %L and %M placeholdersin the pattern layout to be replaced by the filename, the line numberand the function/method name of the signal handler, not the error-throwingmodule. To adjust this, Log::Log4perl has the $caller_depth variable,which defaults to 0, but can be set to positive integer valuesto offset the caller level. Increasingit by one will cause it to log the calling function's parameters, notthe ones of the signal handler.See ``Using Log::Log4perl from wrapper classes'' in Log::Log4perl for moredetails. 

How can I hook up the LWP library with Log::Log4perl?

Or, to put it more generally: How can you utilize a third-partylibrary's embedded logging and debug statements in Log::Log4perl?How can you make them printto configurable appenders, turn them on and off, just as if theywere regular Log::Log4perl logging statements?

The easiest solution is to map the third-party library logging statementsto Log::Log4perl's stealth loggers via a typeglob assignment.

As an example, let's take LWP, one of the most popular Perl modules,which makes handling WWW requests and responses a breeze.Internally, LWP uses its own logging and debugging system,utilizing the following callsinside the LWP code (from the LWP::Debug man page):

        # Function tracing    LWP::Debug::trace('send()');        # High-granular state in functions    LWP::Debug::debug('url ok');        # Data going over the wire    LWP::Debug::conns("read $n bytes: $data");

First, let's assign Log::Log4perl prioritiesto these functions: I'd suggest that"debug()" messages have priority "INFO","trace()" uses "DEBUG" and "conns()" also logs with "DEBUG" ---although your mileage may certainly vary.

Now, in order to transparently hook up LWP::Debug with Log::Log4perl,all we have to do is say

    package LWP::Debug;    use Log::Log4perl qw(:easy);    *trace = *INFO;    *conns = *DEBUG;    *debug = *DEBUG;    package main;    # ... go on with your regular program ...

at the beginning of our program. In this way, every time the, say,"LWP::UserAgent" module calls "LWP::Debug::trace()", it will implicitlycall INFO(), which is the "info()" method of a stealth logger defined forthe Log::Log4perl category "LWP::Debug". Is this cool or what?

Here's a complete program:

    use LWP::UserAgent;    use HTTP::Request::Common;    use Log::Log4perl qw(:easy);    Log::Log4perl->easy_init(        { category => "LWP::Debug",          level    => $DEBUG,          layout   => "%r %p %M-%L %m%n",        });    package LWP::Debug;    use Log::Log4perl qw(:easy);    *trace = *INFO;    *conns = *DEBUG;    *debug = *DEBUG;    package main;    my $ua = LWP::UserAgent->new();    my $resp = $ua->request(GET "http://amazon.com");    if($resp->is_success()) {        print "Success: Received ",              length($resp->content()), "\n";    } else {        print "Error: ", $resp->code(), "\n";    }

This will generate the following output on STDERR:

    174 INFO LWP::UserAgent::new-164 ()    208 INFO LWP::UserAgent::request-436 ()    211 INFO LWP::UserAgent::send_request-294 GET http://amazon.com    212 DEBUG LWP::UserAgent::_need_proxy-1123 Not proxied    405 INFO LWP::Protocol::http::request-122 ()    859 DEBUG LWP::Protocol::collect-206 read 233 bytes    863 DEBUG LWP::UserAgent::request-443 Simple response: Found    869 INFO LWP::UserAgent::request-436 ()    871 INFO LWP::UserAgent::send_request-294     GET http://www.amazon.com:80/exec/obidos/gateway_redirect    872 DEBUG LWP::UserAgent::_need_proxy-1123 Not proxied    873 INFO LWP::Protocol::http::request-122 ()    1016 DEBUG LWP::UserAgent::request-443 Simple response: Found    1020 INFO LWP::UserAgent::request-436 ()    1022 INFO LWP::UserAgent::send_request-294     GET http://www.amazon.com/exec/obidos/subst/home/home.html/    1023 DEBUG LWP::UserAgent::_need_proxy-1123 Not proxied    1024 INFO LWP::Protocol::http::request-122 ()    1382 DEBUG LWP::Protocol::collect-206 read 632 bytes    ...    2605 DEBUG LWP::Protocol::collect-206 read 77 bytes    2607 DEBUG LWP::UserAgent::request-443 Simple response: OK    Success: Received 42584

Of course, in this way, the embedded logging and debug statements withinLWP can be utilized in any Log::Log4perl way you can think of. You canhave them sent to different appenders, block them based on thecategory and everything else Log::Log4perl has to offer.

Only drawback of this method: Steering logging behavior via categoryis always based on the "LWP::Debug" package. Although the loggingstatements reflect the package name of the issuing module properly,the stealth loggers in "LWP::Debug" are all of the category "LWP::Debug".This implies that you can't control the logging behavior based on thepackage that's initiating a log request (e.g. LWP::UserAgent) but onlybased on the package that's actually executing the logging statement,"LWP::Debug" in this case.

To work around this conundrum, we need to write a wrapper function andplant it into the "LWP::Debug" package. It will determine the caller andcreate a logger bound to a category with the same name as the caller'spackage:

    package LWP::Debug;    use Log::Log4perl qw(:levels get_logger);    sub l4p_wrapper {        my($prio, @message) = @_;        $Log::Log4perl::caller_depth += 2;        get_logger(scalar caller(1))->log($prio, @message);        $Log::Log4perl::caller_depth -= 2;    }    no warnings 'redefine';    *trace = sub { l4p_wrapper($INFO, @_); };    *debug = *conns = sub { l4p_wrapper($DEBUG, @_); };    package main;    # ... go on with your main program ...

This is less performant than the previous approach, because everylog request will request a reference to a logger first, then callthe wrapper, which will in turn call the appropriate log function.

This hierarchy shift has to be compensated for by increasing$Log::Log4perl::caller_depth by 2 before calling the log functionand decreasing it by 2 right afterwards. Also, the "l4p_wrapper"function shown above calls caller(1) which determines the nameof the package two levels down the calling hierarchy (andtherefore compensates for both the wrapper function and theanonymous subroutine calling it).

"no warnings 'redefine'" suppresses a warning Perl would generateotherwiseupon redefining "LWP::Debug"'s "trace()", "debug()" and "conns()"functions. In case you use a perl prior to 5.6.x, you needto manipulate $^W instead.

To make things easy for you when dealing with LWP, Log::Log4perl 0.47introduces "Log::Log4perl->infiltrate_lwp()" which does exactly theabove. 

What if I need dynamic values in a static Log4perl configuration file?

Say, your application uses Log::Log4perl for logging andtherefore comes with a Log4perl configuration file, specifying the loggingbehavior.But, you also want it to take command line parameters to set valueslike the name of the log file.How can you haveboth a static Log4perl configuration file and a dynamic command lineinterface?

As of Log::Log4perl 0.28, every value in the configuration filecan be specified as a Perl hook. So, instead of saying

    log4perl.appender.Logfile.filename = test.log

you could just as well have a Perl subroutine deliver the valuedynamically:

    log4perl.appender.Logfile.filename = sub { logfile(); };

given that "logfile()" is a valid function in your "main" packagereturning a string containing the path to the log file.

Or, think about using the value of an environment variable:

    log4perl.appender.DBI.user = sub { $ENV{USERNAME} };

When "Log::Log4perl->init()" parses the configurationfile, it will notice the assignment above because of its"sub {...}" pattern and treat it in a special way:It will evaluate the subroutine (which can containarbitrary Perl code) and take its return value as the right sideof the assignment.

A typical application would be called like this on the command line:

    app                # log file is "test.log"    app -l mylog.txt   # log file is "mylog.txt"

Here's some sample code implementing the command line interface above:

    use Log::Log4perl qw(get_logger);    use Getopt::Std;    getopt('l:', \our %OPTS);    my $conf = q(    log4perl.category.Bar.Twix         = WARN, Logfile    log4perl.appender.Logfile          = Log::Log4perl::Appender::File    log4perl.appender.Logfile.filename = sub { logfile(); };    log4perl.appender.Logfile.layout   = SimpleLayout    );    Log::Log4perl::init(\$conf);    my $logger = get_logger("Bar::Twix");    $logger->error("Blah");    ###########################################    sub logfile {    ###########################################        if(exists $OPTS{l}) {            return $OPTS{l};        } else {            return "test.log";        }    }

Every Perl hook may contain arbitrary perl code,just make sure to fully qualify eventual variable names(e.g. %main::OPTS instead of %OPTS).

SECURITY NOTE: this feature means arbitrary perl codecan be embedded in the config file. In the rare casewhere the people who have access to your config fileare different from the people who write your code andshouldn't have execute rights, you might want to call

    $Log::Log4perl::Config->allow_code(0);

before you call init(). This will prevent Log::Log4perl fromexecuting any Perl code in the config file (includingcode for custom conversion specifiers(see ``Custom cspecs'' in Log::Log4perl::Layout::PatternLayout). 

How can I roll over my logfiles automatically at midnight?

Long-running applications tend to produce ever-increasing logfiles.For backup and cleanup purposes, however, it is often desirable to movethe current logfile to a different location from time to time andstart writing a new one.

This is a non-trivial task, because it has to happen in sync withthe logging system in order not to lose any messages in the process.

Luckily, Mark Pfeiffer's "Log::Dispatch::FileRotate" appenderworks well with Log::Log4perl to rotate your logfiles in a variety of ways.

Note, however, that having the application deal with rotating a logfile is not cheap. Among other things, it requires locking the log filewith every write to avoid race conditions.There are good reasons to use external rotators like "newsyslog"instead.See the entry "How can I rotate a logfile with newsyslog?" in theFAQ for more information on how to configure it.

When using "Log::Dispatch::FileRotate",all you have to do is specify it in your Log::Log4perl configuration fileand your logfiles will be rotated automatically.

You can choose between rolling based on a maximum size (``roll if greaterthan 10 MB'') or based on a date pattern (``roll everyday at midnight'').In both cases, "Log::Dispatch::FileRotate" allows you to define anumber "max" of saved files to keep around until it starts overwritingthe oldest ones. If you set the "max" parameter to 2 and the name ofyour logfile is "test.log", "Log::Dispatch::FileRotate" willmove "test.log" to "test.log.1" on the first rollover. On the secondrollover, it will move "test.log.1" to "test.log.2" and then "test.log"to "test.log.1". On the third rollover, it will move "test.log.1" to"test.log.2" (therefore discarding the old "test.log.2") and"test.log" to "test.log.1". And so forth. This way, there's alwaysgoing to be a maximum of 2 saved log files around.

Here's an example of a Log::Log4perl configuration file, defining adaily rollover at midnight (date pattern "yyyy-MM-dd"), keepinga maximum of 5 saved logfiles around:

    log4perl.category         = WARN, Logfile    log4perl.appender.Logfile = Log::Dispatch::FileRotate    log4perl.appender.Logfile.filename    = test.log    log4perl.appender.Logfile.max         = 5    log4perl.appender.Logfile.DatePattern = yyyy-MM-dd    log4perl.appender.Logfile.TZ          = PST    log4perl.appender.Logfile.layout = \        Log::Log4perl::Layout::PatternLayout    log4perl.appender.Logfile.layout.ConversionPattern = %d %m %n

Please see the "Log::Dispatch::FileRotate" documentation for details."Log::Dispatch::FileRotate" is available on CPAN. 

What's the easiest way to turn off all logging, even with a lengthy Log4perl configuration file?

In addition to category-based levels and appender thresholds,Log::Log4perl supports system-wide logging thresholds. This is theminimum level the system will require of any logging events in order for themto make it through to any configured appenders.

For example, putting the line

    log4perl.threshold = ERROR

anywhere in your configuration file will limit any output to any appenderto events with priority of ERROR or higher (ERROR or FATAL that is).

However, in order to suppress all logging entirely, you need to use apriority that's higher than FATAL: It is simply called "OFF", and it is neverused by any logger. By definition, it is higher than the highestdefined logger level.

Therefore, if you keep the line

    log4perl.threshold = OFF

somewhere in your Log::Log4perl configuration, the system will be quietas a graveyard. If you deactivate the line (e.g. by commenting it out),the system will, upon config reload, snap back to normal operation, providinglogging messages according to the rest of the configuration file again. 

How can I log DEBUG and above to the screen and INFO and above to a file?

You need one logger with two appenders attached to it:

    log4perl.logger = DEBUG, Screen, File    log4perl.appender.Screen   = Log::Log4perl::Appender::Screen    log4perl.appender.Screen.layout = SimpleLayout    log4perl.appender.File   = Log::Log4perl::Appender::File    log4perl.appender.File.filename = test.log    log4perl.appender.File.layout = SimpleLayout    log4perl.appender.Screen.Threshold = INFO

Since the file logger isn't supposed to get any messages with a priorityless than INFO, the appender's "Threshold" setting blocks those out,although the logger forwards them.

It's a common mistake to think you can define two loggers for this, butit won't work unless those two loggers have different categories. If youwanted to log all DEBUG and above messages from the Foo::Bar module to a fileand all INFO and above messages from the Quack::Schmack module to thescreen, then you could have defined two loggers with different levels"log4perl.logger.Foo.Bar" (level INFO)and "log4perl.logger.Quack.Schmack" (level DEBUG) and assigned the fileappender to the former and the screen appender to the latter. But what wewanted to accomplish was to route all messages, regardless of which module(or category) they came from, to both appenders. The onlyway to accomplish this is to define the root logger with the lowerlevel (DEBUG), assign both appenders to it, and block unwanted messages atthe file appender ("Threshold" set to INFO). 

I keep getting duplicate log messages! What's wrong?

Having several settings for related categories in the Log4perlconfiguration file sometimes leads to a phenomenon called``message duplication''. It can be very confusing at first,but if thought through properly, it turns out that Log4perl behavesas advertised. But, don't despair, of course there's a number ofways to avoid message duplication in your logs.

Here's a sample Log4perl configuration file that produces thephenomenon:

    log4perl.logger.Cat        = ERROR, Screen    log4perl.logger.Cat.Subcat = WARN, Screen    log4perl.appender.Screen   = Log::Log4perl::Appender::Screen    log4perl.appender.Screen.layout = SimpleLayout

It defines two loggers, one for category "Cat" and one for"Cat::Subcat", which is obviously a subcategory of "Cat".The parent logger has a priority setting of ERROR, the childis set to the lower "WARN" level.

Now imagine the following code in your program:

    my $logger = get_logger("Cat.Subcat");    $logger->warn("Warning!");

What do you think will happen? An unexperienced Log4perl usermight think: "Well, the message is being sent with level WARN, so the"Cat::Subcat" logger will accept it and forward it to theattached "Screen" appender. Then, the message will percolate upthe logger hierarchy, findthe "Cat" logger, which will suppress the message because of itsERROR setting."But, perhaps surprisingly, what you'll get with thecode snippet above is not one but two log messages writtento the screen:

    WARN - Warning!    WARN - Warning!

What happened? The culprit is that once the logger "Cat::Subcat"decides to fire, it will forward the message unconditionallyto all directly or indirectly attached appenders. The "Cat" loggerwill never be asked if it wants the message or not --- the messagewill just be pushed through to the appender attached to "Cat".

One way to prevent the message from bubbling up the loggerhierarchy is to set the "additivity" flag of the subordinate logger to0:

    log4perl.logger.Cat            = ERROR, Screen    log4perl.logger.Cat.Subcat     = WARN, Screen    log4perl.additivity.Cat.Subcat = 0    log4perl.appender.Screen   = Log::Log4perl::Appender::Screen    log4perl.appender.Screen.layout = SimpleLayout

The message will now be accepted by the "Cat::Subcat" logger,forwarded to its appender, but then "Cat::Subcat" will suppressany further action. While this setting avoids duplicate messagesas seen before, it is often not the desired behavior. Messagespercolating up the hierarchy are a useful Log4perl feature.

If you're defining different appenders for the two loggers,one other option is to define an appender threshold for thehigher-level appender. Typically it is set to beequal to the logger's level setting:

    log4perl.logger.Cat           = ERROR, Screen1    log4perl.logger.Cat.Subcat    = WARN, Screen2    log4perl.appender.Screen1   = Log::Log4perl::Appender::Screen    log4perl.appender.Screen1.layout = SimpleLayout    log4perl.appender.Screen1.Threshold = ERROR    log4perl.appender.Screen2   = Log::Log4perl::Appender::Screen    log4perl.appender.Screen2.layout = SimpleLayout

Since the "Screen1" appender now blocks every message witha priority less than ERROR, even if the logger in chargelets it through, the message percolating up the hierarchy isbeing blocked at the last minute and not appended to "Screen1".

So far, we've been operating well within the boundaries of theLog4j standard, which Log4perl adheres to. However, ifyou would really, really like to use a single appenderand keep the message percolation intact without having to dealwith message duplication, there's a non-standard solution for you:

    log4perl.logger.Cat        = ERROR, Screen    log4perl.logger.Cat.Subcat = WARN, Screen    log4perl.appender.Screen   = Log::Log4perl::Appender::Screen    log4perl.appender.Screen.layout = SimpleLayout    log4perl.oneMessagePerAppender = 1

The "oneMessagePerAppender" flag will suppress duplicate messagesto the same appender. Again, that's non-standard. But way cool :). 

How can I configure Log::Log4perl to send me email if something happens?

Some incidents require immediate action. You can't wait until someonechecks the log files, you need to get notified on your pager right away.

The easiest way to do that is by using the "Log::Dispatch::Email::MailSend"module as an appender. It comes with the "Log::Dispatch" bundle andallows you to specify recipient and subject of outgoing emails in the Log4perlconfiguration file:

    log4perl.category = FATAL, Mailer    log4perl.appender.Mailer         = Log::Dispatch::Email::MailSend    log4perl.appender.Mailer.to      = droneAATTpageme.net    log4perl.appender.Mailer.subject = Something's broken!    log4perl.appender.Mailer.layout  = SimpleLayout

The message of every log incident this appender getswill then be forwarded to the givenemail address. Check the "Log::Dispatch::Email::MailSend" documentationfor details. And please make sure there's not a flood of email messagessent out by your application, filling up the recipient's inbox.

There's one caveat you need to know about: The "Log::Dispatch::Email"hierarchy of appenders turns on buffering by default. This means thatthe appender will not send out messages right away but wait until acertain threshold has been reached. If you'd rather have your alertssent out immediately, use

    log4perl.appender.Mailer.buffered = 0

to turn buffering off. 

How can I write my own appender?

First off, Log::Log4perl comes with a set of standard appenders. Then,there's a lot of Log4perl-compatible appenders alreadyavailable on CPAN: Just run a search for "Log::Dispatch" onhttp://search.cpan.org and chances are that what you're looking forhas already been developed, debugged and been used successfullyin production --- no need for you to reinvent the wheel.

Also, Log::Log4perl ships with a nifty database appender namedLog::Log4perl::Appender::DBI --- check it out if talking to databases is yourdesire.

But if you're up for a truly exotic task, you might have to writean appender yourself. That's very easy --- it takes no longerthan a couple of minutes.

Say, we wanted to create an appender of the class"ColorScreenAppender", which logs messagesto the screen in a configurable color. Just create a new classin "ColorScreenAppender.pm":

    package ColorScreenAppender;

Now let's assume that your Log::Log4perlconfiguration file "test.conf" looks like this:

    log4perl.logger = INFO, ColorApp    log4perl.appender.ColorApp=ColorScreenAppender    log4perl.appender.ColorApp.color=blue    log4perl.appender.ColorApp.layout = PatternLayout    log4perl.appender.ColorApp.layout.ConversionPattern=%d %m %n

This will cause Log::Log4perl on "init()" to look for a classColorScreenAppender and call its constructor new(). Let's addnew() to ColorScreenAppender.pm:

    sub new {        my($class, %options) = @_;        my $self = { %options };        bless $self, $class;        return $self;    }

To initialize this appender, Log::Log4perl will calland pass all attributes of the appender as defined in the configurationfile to the constructor as name/value pairs (in this case just one):

    ColorScreenAppender->new(color => "blue");

The new() method listed above stores the contents of the%options hash in the object'sinstance data hash (referred to by $self).That's all for initializing a new appender with Log::Log4perl.

Second, ColorScreenAppender needs to expose a"log()" method, which will be called by Log::Log4perlevery time it thinks the appender should fire. Along with theobject reference (as usual in Perl's object world), log()will receive a list of name/value pairs, of which only the oneunder the key "message" shall be of interest for now since it is themessage string to be logged. At this point, Log::Log4perl has already takencare of joining the message to be a single string.

For our special appender ColorScreenAppender, we're using theTerm::ANSIColor module to colorize the output:

    use Term::ANSIColor;    sub log {        my($self, %params) = @_;        print colored($params{message},                      $self->{color});    }

The color (as configured in the Log::Log4perl configuration file)is available as $self->{color} in the appender object. Don'tforget to return

    1;

at the end of ColorScreenAppender.pm and you're done. Install the new appendersomewhere where perl can find it and try it with a test script like

    use Log::Log4perl qw(:easy);    Log::Log4perl->init("test.conf");    ERROR("blah");

to see the new colored output. Is this cool or what?

And it gets even better: You can write dynamically generated appenderclasses using the "Class::Prototyped" module. Here's an example ofan appender prepending every outgoing message with a configurablenumber of bullets:

    use Class::Prototyped;    my $class = Class::Prototyped->newPackage(      "MyAppenders::Bulletizer",      bullets => 1,      log     => sub {        my($self, %params) = @_;        print "*" x $self->bullets(),              $params{message};      },    );    use Log::Log4perl qw(:easy);    Log::Log4perl->init(\ q{      log4perl.logger = INFO, Bully      log4perl.appender.Bully=MyAppenders::Bulletizer      log4perl.appender.Bully.bullets=3      log4perl.appender.Bully.layout = PatternLayout      log4perl.appender.Bully.layout.ConversionPattern=%m %n    });        # ... prints: "***Boo!\n";    INFO "Boo!";
 

How can I drill down on references before logging them?

If you've got a reference to a nested structure or object, thenyou probably don't want to log it as "HASH(0x81141d4)" but ratherdump it as something like

    $VAR1 = {              'a' => 'b',              'd' => 'e'            };

via a module like Data::Dumper. While it's syntactically correct to say

    $logger->debug(Data::Dumper::Dumper($ref));

this call imposes a huge performance penalty on your applicationif the message is suppressed by Log::Log4perl, because Data::Dumperwill perform its expensive operations in any case, because it doesn'tknow that its output will be thrown away immediately.

As of Log::Log4perl 0.28, there's a better way: Use themessage output filter format as in

    $logger->debug( {filter => \&Data::Dumper::Dumper,                     value  => $ref} );

and Log::Log4perl won't call the filter function unless the message reallygets written out to an appender. Just make sure to pass the whole slew as areference to a hash specifying a filter function (as a sub reference)under the key "filter" and the value to be passed to the filter function in"value").When it comes to logging, Log::Log4perl will call the filter function,pass the "value" as an argument and log the return value.Saves you serious cycles. 

How can I collect all FATAL messages in an extra log file?

Suppose you have employed Log4perl all over your system and you've alreadyactivated logging in various subsystems. On top of that, without disruptingany other settings, how can you collect all FATAL messages all over the systemand send them to a separate log file?

If you define a root logger like this:

    log4perl.logger                  = FATAL, File    log4perl.appender.File           = Log::Log4perl::Appender::File    log4perl.appender.File.filename  = /tmp/fatal.txt    log4perl.appender.File.layout    = PatternLayout    log4perl.appender.File.layout.ConversionPattern= %d %m %n        # !!! Something's missing ...

you'll be surprised to not only receive all FATAL messagesissued anywhere in the system,but also everything else --- gazillions ofERROR, WARN, INFO and even DEBUG messages will end up inyour fatal.txt logfile!Reason for this is Log4perl's (or better: Log4j's) appender additivity.Once alower-level logger decides to fire, the message is going to be forwardedto all appenders upstream --- without further priority checks with theirattached loggers.

There's a way to prevent this, however: If your appender defines aminimum threshold, only messages of this priority or higher are goingto be logged. So, just add

    log4perl.appender.File.Threshold = FATAL

to the configuration above, and you'll get what you wanted in thefirst place: An overall system FATAL message collector. 

How can I bundle several log messages into one?

Would you like to tally the messages arriving at your appender anddump out a summary once they're exceeding a certain threshold?So that something like

    $logger->error("Blah");    $logger->error("Blah");    $logger->error("Blah");

won't be logged as

    Blah    Blah    Blah

but as

    [3] Blah

instead? If you'd like to hold off on logging a message until it has beensent a couple of times, you can roll that out by creating a bufferedappender.

Let's define a new appender like

    package TallyAppender;    sub new {        my($class, %options) = @_;        my $self = { maxcount => 5,                     %options                   };        bless $self, $class;        $self->{last_message}        = "";        $self->{last_message_count}  = 0;        return $self;    }

with two additional instance variables "last_message" and"last_message_count", storing the content of the last message sentand a counter of how many times this has happened. Also, it featuresa configuration parameter "maxcount" which defaults to 5 in thesnippet above but can be set in the Log4perl configuration file like this:

    log4perl.logger = INFO, A    log4perl.appender.A=TallyAppender    log4perl.appender.A.maxcount = 3

The main tallying logic lies in the appender's "log" method,which is called every time Log4perl thinks a message needs to get loggedby our appender:

    sub log {        my($self, %params) = @_;            # Message changed? Print buffer.        if($self->{last_message} and           $params{message} ne $self->{last_message}) {            print "[$self->{last_message_count}]: " .                  "$self->{last_message}";            $self->{last_message_count} = 1;            $self->{last_message} = $params{message};            return;        }        $self->{last_message_count}++;        $self->{last_message} = $params{message};            # Threshold exceeded? Print, reset counter        if($self->{last_message_count} >=           $self->{maxcount}) {            print "[$self->{last_message_count}]: " .                  "$params{message}";            $self->{last_message_count} = 0;            $self->{last_message}       = "";            return;        }    }

We basically just check if the oncoming message in $param{message}is equal to what we've saved before in the "last_message" instancevariable. If so, we're increasing "last_message_count".We print the message in two cases: If the new message is differentthan the buffered one, because then we need to dump the old stuffand store the new. Or, if the counter exceeds the threshold, asdefined by the "maxcount" configuration parameter.

Please note that the appender always gets the fully rendered message andjust compares it as a whole --- so if there's a date/timestamp in there,that might confuse your logic. You can work around this by specifying%m %n as a layout and add the date later on in the appender. Or, makethe comparison smart enough to omit the date.

At last, don't forget what happens if the program is being shut down.If there's still messages in the buffer, they should be printed outat that point. That's easy to do in the appender's DESTROY method,which gets called at object destruction time:

    sub DESTROY {        my($self) = @_;        if($self->{last_message_count}) {            print "[$self->{last_message_count}]: " .                  "$self->{last_message}";            return;        }    }

This will ensure that none of the buffered messages are lost.Happy buffering! 

I want to log ERROR and WARN messages to different files! How can I do that?

Let's assume you wanted to have each logging statement written to adifferent file, based on the statement's priority. Messages with priority"WARN" are supposed to go to "/tmp/app.warn", events prioritizedas "ERROR" should end up in "/tmp/app.error".

Now, if you define two appenders "AppWarn" and "AppError"and assign them both to the root logger,messages bubbling up from any loggers below will be logged by bothappenders because of Log4perl's message propagation feature. If you limittheir exposure via the appender threshold mechanism and set"AppWarn"'s threshold to "WARN" and "AppError"'s to "ERROR", you'llstill get "ERROR" messages in "AppWarn", because "AppWarn"'s "WARN"setting will just filter out messages with a lower priority than"WARN" --- "ERROR" is higher and will be allowed to pass through.

What we need for this is a Log4perl Custom Filter, available withLog::Log4perl 0.30.

Both appenders need to verify thatthe priority of the oncoming messages exactly matches the prioritythe appender is supposed to log messages of. To accomplish this task,let's define two custom filters, "MatchError" and "MatchWarn", which,when attached to their appenders, will limit messages passed on to themto those matching a given priority:

    log4perl.logger = WARN, AppWarn, AppError        # Filter to match level ERROR    log4perl.filter.MatchError = Log::Log4perl::Filter::LevelMatch    log4perl.filter.MatchError.LevelToMatch  = ERROR    log4perl.filter.MatchError.AcceptOnMatch = true        # Filter to match level WARN    log4perl.filter.MatchWarn  = Log::Log4perl::Filter::LevelMatch    log4perl.filter.MatchWarn.LevelToMatch  = WARN    log4perl.filter.MatchWarn.AcceptOnMatch = true        # Error appender    log4perl.appender.AppError = Log::Log4perl::Appender::File    log4perl.appender.AppError.filename = /tmp/app.err    log4perl.appender.AppError.layout   = SimpleLayout    log4perl.appender.AppError.Filter   = MatchError        # Warning appender    log4perl.appender.AppWarn = Log::Log4perl::Appender::File    log4perl.appender.AppWarn.filename = /tmp/app.warn    log4perl.appender.AppWarn.layout   = SimpleLayout    log4perl.appender.AppWarn.Filter   = MatchWarn

The appenders "AppWarn" and "AppError" defined above are logging to "/tmp/app.warn" and"/tmp/app.err" respectively and have the custom filters "MatchWarn" and "MatchError"attached.This setup will direct all WARN messages, issued anywhere in the system, to /tmp/app.warn (andERROR messages to /tmp/app.error) --- without any overlaps. 

On our server farm, Log::Log4perl configuration files differ slightly from host to host. Can I roll them all into one?

You sure can, because Log::Log4perl allows you to specify attribute valuesdynamically. Let's say that one of your appenders expects the host's IP addressas one of its attributes. Now, you could certainly roll out differentconfiguration files for every host and specify the value like

    log4perl.appender.MyAppender    = Log::Log4perl::Appender::SomeAppender    log4perl.appender.MyAppender.ip = 10.0.0.127

but that's a maintenance nightmare. Instead, you can have Log::Log4perlfigure out the IP address at configuration time and set the appender'svalue correctly:

        # Set the IP address dynamically    log4perl.appender.MyAppender    = Log::Log4perl::Appender::SomeAppender    log4perl.appender.MyAppender.ip = sub { \       use Sys::Hostname; \       use Socket; \       return inet_ntoa(scalar gethostbyname hostname); \    }

If Log::Log4perl detects that an attribute value starts with something like"sub {...", it will interpret it as a perl subroutine which is to be executedonce at configuration time (not runtime!) and its return value isto be used as the attribute value. This comes in handyfor rolling out applications where Log::Log4perl configuration filesshow small host-specific differences, because you can deploy the unmodifiedapplication distribution on all instances of the server farm. 

Log4perl doesn't interpret my backslashes correctly!

If you're using Log4perl's feature to specify the configuration as astring in your program (as opposed to a separate configuration file),chances are that you've written it like this:

    # *** WRONG! ***    Log::Log4perl->init( \ <<END_HERE);        log4perl.logger = WARN, A1        log4perl.appender.A1 = Log::Log4perl::Appender::Screen        log4perl.appender.A1.layout = \            Log::Log4perl::Layout::PatternLayout        log4perl.appender.A1.layout.ConversionPattern = %m%n    END_HERE    # *** WRONG! ***

and you're getting the following error message:

    Layout not specified for appender A1 at .../Config.pm line 342.

What's wrong? The problem is that you're using a here-document withsubstitution enabled ("<<END_HERE") and that Perl won'tinterpret backslashes at line-ends as continuation characters butwill essentially throw them out. So, in the code above, the layout linewill look like

    log4perl.appender.A1.layout =

to Log::Log4perl which causes it to report an error. To interpret the backslashat the end of the line correctly as a line-continuation character, usethe non-interpreting mode of the here-document like in

    # *** RIGHT! ***    Log::Log4perl->init( \ <<'END_HERE');        log4perl.logger = WARN, A1        log4perl.appender.A1 = Log::Log4perl::Appender::Screen        log4perl.appender.A1.layout = \            Log::Log4perl::Layout::PatternLayout        log4perl.appender.A1.layout.ConversionPattern = %m%n    END_HERE    # *** RIGHT! ***

(note the single quotes around 'END_HERE') or use "q{...}"instead of a here-document and Perl will treat the backslashes atline-end as intended. 

I want to suppress certain messages based on their content!

Let's assume you've plastered all your functions with Log4perlstatements like

    sub some_func {        INFO("Begin of function");        # ... Stuff happens here ...        INFO("End of function");    }

to issue two log messages, one at the beginning and one at the end ofeach function. Now you want to suppress the message at the beginningand only keep the one at the end, what can you do? You can't use the categorymechanism, because both messages are issued from the same package.

Log::Log4perl's custom filters (0.30 or better) provide an interface for theLog4perl user to step in right before a message gets logged and decide ifit should be written out or suppressed, based on the message content or otherparameters:

    use Log::Log4perl qw(:easy);    Log::Log4perl::init( \ <<'EOT' );        log4perl.logger             = INFO, A1        log4perl.appender.A1        = Log::Log4perl::Appender::Screen        log4perl.appender.A1.layout = \            Log::Log4perl::Layout::PatternLayout        log4perl.appender.A1.layout.ConversionPattern = %m%n        log4perl.filter.M1 = Log::Log4perl::Filter::StringMatch        log4perl.filter.M1.StringToMatch = Begin        log4perl.filter.M1.AcceptOnMatch = false        log4perl.appender.A1.Filter = M1EOT

The last four statements in the configuration above are defining a customfilter "M1" of type "Log::Log4perl::Filter::StringMatch", which comes withLog4perl right out of the box and allows you to define a text pattern to match(as a perl regular expression) and a flag "AcceptOnMatch" indicatingif a match is supposed to suppress the message or let it pass through.

The last line then assigns this filter to the "A1" appender, which willcall it every time it receives a message to be logged and throw allmessages out not matching the regular expression "Begin".

Instead of using the standard "Log::Log4perl::Filter::StringMatch" filter,you can define your own, simply using a perl subroutine:

    log4perl.filter.ExcludeBegin  = sub { !/Begin/ }    log4perl.appender.A1.Filter   = ExcludeBegin

For details on custom filters, check Log::Log4perl::Filter. 

My new module uses Log4perl --- but what happens if the calling program didn't configure it?

If a Perl module uses Log::Log4perl, it will typically rely on thecalling program to initialize it. If it is using Log::Log4perl in ":easy"mode, like in

    package MyMod;    use Log::Log4perl qw(:easy);    sub foo {        DEBUG("In foo");    }    1;

and the calling program doesn't initialize Log::Log4perl at all (e.g. becauseit has no clue that it's available), Log::Log4perl will silentlyignore all logging messages. However, if the module is using Log::Log4perlin regular mode like in

    package MyMod;    use Log::Log4perl qw(get_logger);    sub foo {        my $logger = get_logger("");        $logger->debug("blah");    }    1;

and the main program is just using the module like in

    use MyMode;    MyMode::foo();

then Log::Log4perl will also ignore all logging messages butissue a warning like

    Log4perl: Seems like no initialization happened.    Forgot to call init()?

(only once!) to remind novice users to not forget to initializethe logging system before using it.However, if you want to suppress this message, justadd the ":nowarn" target to the module's "use Log::Log4perl" call:

    use Log::Log4perl qw(get_logger :nowarn);

This will have Log::Log4perl silently ignore all logging statements ifno initialization has taken place. If, instead of using init(), you'reusing Log4perl's API to define loggers and appenders, the samenotification happens if no call to add_appenders() is made, i.e. noappenders are defined.

If the module wants to figure out if some other program part hasalready initialized Log::Log4perl, it can do so by calling

    Log::Log4perl::initialized()

which will return a true value in case Log::Log4perl has been initializedand a false value if not. 

How can I synchronize access to an appender?

If you're using the same instance of an appender in multiple processes,and each process is passing on messages to the appender in parallel,you might end up with overlapping log entries.

Typical scenarios include a file appender that you create in the mainprogram, and which will then be shared between the parent and aforked child process. Or two separate processes, each initializing aLog4perl file appender on the same logfile.

Log::Log4perl won't synchronize access to the shared logfile bydefault. Depending on your operating system's flush mechanism,buffer size and the size of your messages, there's a small chance ofan overlap.

The easiest way to prevent overlapping messages in logfiles written toby multiple processes is setting thefile appender's "syswrite" flag along with a file write mode of "append".This makes sure that"Log::Log4perl::Appender::File" uses "syswrite()" (which is guaranteedto run uninterrupted) instead of "print()" which might bufferthe message or get interrupted by the OS while it is writing. And in"ap