http://www.perlmonks.org?node_id=531030

Update: code and POD updated based on suggestions as of 2006-Feb-23

I have been a fan of Log::Log4Perl for a long time, as it's one of the most comprehensive, configurable, and just generally nifty loggers out there. Sometimes, though, it's a bit too much, so there are things like Log::Simple to fill the gap.

What I really wanted, though, was a logging facility that wouldn't get in my way, even if it was only suitable for small and/or simple scripts.

What I came up with is a module that I temporarily just named 'Log' (yes, I know, horrible namespace choice), and it's here for some peer review. The goals were:

  1. An interface that doesn't get in the way of "real" code.
  2. Automagical logging of die/warn events
  3. Easy configuration, in as few lines of code as possible.
  4. Pure perl
  5. Suitable and reasonable defaults.

An interface that doesn't get in the way of "real" code.

I gave in to prototypes to make the interface mimic that of warn:

info 'This is an info log item'. debug "the value of this variable is: '$this'"

Automagical logging of die/warn events

Custom import function that hooks into $SIG{__DIE__} and $SIG{__WARN__} provides drop-in logging of those events, while propagating them. Any code that use warn or die (unless it has its own custom signal handlers that don't chain) gets logging of those functions just by use Log. (Again with the bad namespace, I know, I know).

Easy configuration, in as few lines of code as possible.

Custom import function allows for one-line setup:

# log die, warn, info, and debug events to mylog.log, but don't # show debug events on the console. use Log ( file=>'mylog.log', warn => 2, info => 2, debug => 1 );

Pure perl

No XS, and no dependencies on modules outside the Perl core distribution.

Suitable and reasonable defaults.

Without any parameters to use Log, the logfile name is the name of the file from which use Log is called with '.log' appended ('myscript.pl' logs to 'myscript.pl.log').

The logging level defaults in such a way that all die, warn, and info events are logged, and die and warn events are propagated; trace and debug are skipped. Die events are always logged and propagated (well, unless someone customizes a signal handler that bypasses this module).

Known limitations

  1. The name is bad. Really bad. I know that.
  2. Custom signal handlers that don't chain could prevent warn/die from being logged. It's an easy workaround (call Log::warn or Log::die, as appropriate, from the handler), and I'm not sure I can (or should) "fix" it.
  3. Very, very simplistic. That's intentional, and this is not a replacement for things like Log::Log4Perl on complex applications. It's a niche to provide easy logging for existing code and/or simple solutions.
  4. Most decidedly not thread-safe. If a module calls this, and so did its parent script, and for some reason they want to write to the same log, there will be problems. I'm not sure how to address that.

I'm sure there is much more (I am still significantly short of any kind of Perl Master status!), and I'd like to know about the issues, considerations, suggestions for improvement, wheels I might be reinventing (even though I did look through CPAN, I miss things all the time...), etc.

All I ask is: (a)please no name-space discussions, I know 'Log' is a horrible choice; and (b)please be a little verbose explaining issues/suggesting alternatives -- if I suck, that's fine, but I want to understand how I suck and how to stop. ;-)

Thanks in advance!

package Log; #===================================================================== +========== # $Id: Log.pm,v 1.8 2006-02-22 20:05:16 radmat Exp $ # Logging package for info/warn/die/debug/trace #===================================================================== +========== use strict; use warnings; our $VERSION = sprintf "%d.%03d", q$Revision: 1.8 $ =~ /: (\d+)\.(\d+) +/; #CVS #__modules__ use Fcntl; use POSIX qw[_exit strftime]; #use subs qw[warn die]; require Exporter; our @ISA = 'Exporter'; our @EXPORT = qw[info debug trace]; #__globals__ our $logfile = ( caller(0) )[0] . '.log'; # Default to main.log our ( $debug, $trace ) = ( 0, 0 ); # No logging of debug() a +nd trace() our ( $info, $warn ) = ( 1, 2 ); # Log info(), Log and pri +nt warn() our $seq = 0; # Session sequence our $line_format = '%s %d.%04d %s'; # Line format (see POD) our $time_format = '%Y-%m-%dT%H:%M:%S'; # POSIX strftime format our $log_umask = 0111; #__subroutines__ #_____________________________________________________________________ + import()_ sub import { # import - override Exporter->import my $me = shift; if ( @_ == 1 ) { $logfile = shift } elsif ( @_ % 2 == 0 ) { my %parm = @_; $logfile = $parm{file} if defined $parm{file}; $debug = $parm{debug} if defined $parm{debug}; $trace = $parm{trace} if defined $parm{trace}; $info = $parm{info} if defined $parm{info}; $warn = $parm{'warn'} if defined $parm{'warn'}; $line_format = $parm{lineform} if defined $parm{lineform}; $time_format = $parm{timeform} if defined $parm{timeform}; $log_umask = $parm{'umask'} if defined $parm{'umask'}; } else { } # TODO ? strings subs for 0/1/2 # TODO per-package configuration umask $log_umask; sysopen( LOG, $logfile, O_WRONLY | O_APPEND | O_CREAT, 0777 ) or die("Cannot log to $logfile: $!"); select LOG; $| = 1; select STDOUT; $SIG{__WARN__} = sub { Log::warn(@_) }; $SIG{__DIE__} = sub { Log::die(@_) }; $me->export_to_level( 1, $me, @EXPORT ); print LOG "\n"; info('Logging started'); } #_____________________________________________________________________ +__ _msg()_ sub _msg { # _msg ( \@msgarray ) my @a = @{ $_[0] }; foreach (@a) { unless ( defined $_ ) { $_ = ''; next; } s/[\r\n]+/ /g; } return join( ' ', @a ); } #_____________________________________________________________________ +__ _log()_ sub _log { # _log ( ) my $time = strftime( $time_format, localtime ); printf LOG $line_format."\n", $time, $$, $seq++, _msg( \@_ ); } #_____________________________________________________________________ +__ warn()_ sub warn ($) { # warn ( ) _log( 'W:', @_ ) if $warn; CORE::warn(@_) if $warn == 2; } #_____________________________________________________________________ +___ die()_ sub die ($) { # die ( ) _log( 'X:', @_ ); CORE::die(@_); } #_____________________________________________________________________ +__ info()_ sub info ($) { # info ( ) return undef unless $info; _log( 'I:', @_ ); print STDERR _msg( \@_ ), "\n" if $info == 2; } #_____________________________________________________________________ +_ debug()_ sub debug ($) { # debug ( ) return undef unless $debug; _log( 'D:', @_ ); print STDERR '. Debug:', _msg( \@_ ), "\n" if $debug == 2; } #_____________________________________________________________________ +_ trace()_ sub trace ($) { # trace ( ) return undef unless $trace; _log( 'T:', @_ ); print STDERR '* Trace:', _msg( \@_ ), "\n" if $trace == 2; } 1; # modules must return a true value. __END__


NAME

Log ($Revision: 1.9 $) - Logging package for info/warn/die/debug/trace

top


SYNOPSIS

    use Log;
    
    warn  'hello';
    info  'this is an information statement';
    trace 'this is a trace log item';
    debug 'this is a debug log item';
    die   'Game over, man: game over!';

top


DESCRIPTION

Log is a simple, lightweight logging system designed to promote logging in code by requiring a minimum of configuration, automatic logging of warn and die events, and an interface that doesn't get in the way of functional code.

When loaded, Log exports info, debug, and trace, then binds WARN and DIE events to its internal warn and die methods. These latter two end by calling CORE::warn and CORE::die, respectively, so code that depends on the default warn and die behavior will continue to work. This makes Log ideal for dropping into existing code to provide a minimal warn/die log.

Log will always record and propagate DIE events. By default, it will also record WARN events and calls to info; the WARN events will be propagated, while the info calls will be silently logged. This behavior can be altered during import: see import for more.

The default log file name is the package name of the script or module from which Log is imported, appended with '.log'. For example, a script will use a log named main.log. This can be altered during import: see import for more.

top


PRIVATE METHODS

import
Overrides Exporter::import, causes info, debug, and trace to be exported, and attaches global WARN and DIE signal handlers to our versions of warn and die, respectively. Also opens the log file handle and processes import parameters. This method is called during use Log.

To change default behaviors (see SYNOPSIS), parameters can be passed to import as a named-pair hash.

To specify a filename to log to, overriding the default:

    use Log ( file => 'myfile.txt' );

To change the level of verbosity for each logging type:

    use Log (
              warn  => 2,  # 2 means log and print to console
              info  => 1,  # 1 means log only
              debug => 1,
              trace => 0,  # 0 means ignore these!
            );

The verbosity of the die type cannot be altered, it is always effectively '2'. Setting warn's level to 1 will prevent warnings from propagating via CORE::warn, but will still log them; setting its value to 0 will entirely supress warnings.

Default values are ( warn=>2, info=>1, debug=>0, trace=>0 ).

To change the format of the line or time-stamp, use 'lineform' and 'timeform', respectively. See LOG FILE FORMAT for more information.

When the log file is created, a mode of 0777 is passed, mitigated by a umask of 0111, resulting in a default mode of 0666 (rw-rw-rw). This can be altered during import using the 'umask' parameter.

    use Log ( umask => 0177 );

Note that this is an octal value, not a string or decimal. See the umask documentation for more information.

_log
Responsible for writing to the log. Accepts a list of scalars, prepending them with date stamp and sequence number before writing them to the log. Before writing, scalars are passed through _msg.

_msg
Message preprocessor. Accepts a list of scalars; undefined values are converted to empty strings and all strings have line endings converted to spaces before they are joined (with a space between elements) into a single scalar, whch is returned.

top


PUBLIC METHODS

warn
While not exported directly, this method is bound to $SIG{__WARN__} and is responsible for recording and propagating warnings. When $warn is 1, warnings are logged only; at 0, warnings are suppressed.

Custom handlers attached to $SIG{__WARN__} should take care to call Log::warn(@_), or warnings may not be logged. If using such handlers, be sure that $warn < 2.

die
While not exported directly, this method is bound to $SIG{__DIE__} and is responsible for recording and propagating exceptions. This behavior cannot be altered.

Even exceptions caught from inside an eval block will be logged; it is a good practice to do something like:

    eval {
        sub_which_could_die();
    };
    if ($@) {
        info "Caught: $@"

        # handle the exception
    }

In this way, the log will show the exception being thrown and being caught (assuming $info > 0), making for much more sensible reading.

Custom handlers attached to $SIG{__DIE__} should take care to call Log::die(@_), or exceptions may not be logged.

info
Information statements. By default, these are logged only ($info is set to 1). Conceptually, info statements should convey important events. For example, major decisions during logical processing are prime candidates for recording via info.

The level of verbosity can be adjusted at run time via $info:


    $Log::info = 2;
    info 'This will be in the log and on the screen';
    $Log::info = 1;
    info 'This will be logged only';

This is not recommended, as it makes it very difficult to adjust these values globally via import.

Accepts a single scalar.

debug
Debug statements. By default, these are suppressed ($debug is set to 0). Conceptually, debug statements should record information that isn't important during normal conditions, but might be helpful in tracing down code or environmental problems. For example, noting states of important variables at key locations, etc.

The level of verbosity can be adjusted at run time via $debug; see info for a related example.

Accepts a single scalar.

trace
Trace statements. By default, these are suppressed ($trace is set to 0). Conceptually, trace statements should record extremely detailed operational information that is helpful in locating difficult-to-find problems. For example, entering and exiting subs, data before and after transformations, etc.

When activated it, this should be extremely verbose.

The level of verbosity can be adjusted at run time via $trace; see info for a related example.

Accepts a single scalar.

top


LOG FILE FORMAT

The log file format for Log is designed to be easy to parse with code, yet reasonable for a human to read as well. There is one message per line in the following format (followed by an example):

    YYYY-mm-ddTHH:MM:SS <pid>.<seq> TYPE: Message text
    2006-02-17T10:00:32 12345.0000 I: Logging started

Each time Log is imported, the logfile has a blank line appended and is issued an info event of 'Logging started' with a sequence number of 0. Dates are in ISO 8601 format without fractional seconds or timezone information.

The TYPE field is one of T, D, I, W, X; these map to trace, debug, info, warn, and die (exception) events, respectively.

The format of this line can be altered using the 'lineform' import instruction. Its value is a printf style format string for the list of values timestamp, pid, seq, message. The format will have a newline appended before use. Be certain not to use tainted user input here!

The format of the timestamp may be altered using the 'timeform' import instruction, similar to 'lineform' above; the format string will be passed to the POSIX strftime function. The warning about tainted user data above applies here as well.

Look for Log::Parser in the future.

top


<-radiant.matrix->
A collection of thoughts and links from the minds of geeks
The Code that can be seen is not the true Code
I haven't found a problem yet that can't be solved by a well-placed trebuchet