RFC: A simple and badly-named logging module

[radiantmatrix]

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
• SYNOPSIS
• DESCRIPTION
• PRIVATE METHODS
• PUBLIC METHODS
• LOG FILE FORMAT

---

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

---

[YuckFoo]

radiantmatrix,

I like it, but here is a wish list:

* Default log file permissions 666. Setting umask in the main program doesn't seem to affect the log file permissions, not sure why.

* strftime string configurable. ISO 8601 be damned, the 'T' between date and time is annoying.

* PID logged instead of sequence number. This would allow me to unravel multiple simultaneous runs of the program. The sequence numbers can be derived later by the log parser.

* Record $0 and @ARGV in the 'Logging started' message.

* Line header shorter. Golf it a bit to leave more space for the good stuff. The colons do nothing for me and a single character T, D, I, W, X is as good as TRCE, DBUG, INFO, WARN, XCPT. How about:

20060217 155643 12345 I Logging started ./tryl -this -that other
20060217 155643 12345 W hello at ./tryl line 8.
20060217 155643 12345 I this is an information statement
20060217 155643 12345 X Game over, man: game over! at ./tryl line 12.

instead of:

2006-02-17T15:56:43      0: INFO: Logging started
2006-02-17T15:56:43      1: WARN: hello at ./tryl line 8.
2006-02-17T15:56:43      2: INFO: this is an information statement
2006-02-17T15:56:43      3: XCPT: Game over, man: game over! at ./tryl
+ line 12.

LogFoo

[radiantmatrix]

I've put most of these on my todo list, excellent suggestions! Some points...

1. I agree that the TDIWX set is better than the longer versions, though I think I might make that configurable.
2. Using $0 and @ARGV are good ideas, but if this is used in a module, not a script, that isn't useful. And, since it's very easy for a script author to simply info 'Started '.$0.join(' '.@ARGV);, I have a hard time justifying that as default module behavior. I'd be interested in opposing arguments if I'm missing something.
3. PID logging is a good idea, but I will be keeping the sequence numbers as an option (appended to the PID).
4. I see your points about the ISO8601 format. Enough, in fact, to make the strftime format param configurable. However, I'm leaving 8601 as the default because its a standard, and I think standards make the most reasonable default. Hopefully, with the configurable format, everyone wins.

Thanks so much for the feedback! Extremely useful.

[xdg]

My first impression is that it's a nice little utility!

My second impression is that I'd like to see something a little more like a unix syslog instead of the 0, 1, 2 constants. E.g. set a destination for all events of a given level or better, choose different files for different types.

use Log (
    trace => "everything.log",
    info  => "info_or_better.log",
    info  => \STDERR,  # also echo info or higher to STDERR
)

I'm not so sure that's really the way I'd want it, but maybe it will give you some ideas.

Finally, I would definitely not use globals like $Log::filename or $Log::info. Consider storing these in a hash keyed on the caller's package. This will allow modular programs to use your module differently in different parts of the program.

[radiantmatrix]

I'd love to use constants instead of 0/1/2, but since I'm doing configuration during import, the constants wouldn't be available during the configuration. I could accept string values, something like:

use Log ( warn => 'BOTH', info => 'LOG', debug => 'QUIET' );

In this particular case, I don't think the 0/1/2 division is all that unintuitive. At its core, it's boolean: should I log warnings? yes=>1, no=>0. I admit the '2' is more of a stretch, but considering any mode set to 2 logs to 2 places (STDERR and logfile), I don't think it's very far-fetched. So, I'm undecided about that one.

Your other suggestions are all good, but they suggest, to me, that you'd want one of the already-existing log modules rather than this one.

For syslog-style logging, if you need or want that, you're better off with one of the existing log modules anyhow (like Sys::Syslog or the mother of them all, Log::Log4Perl), so I'm not sure it's worth the work to implement properly.

The globals suggestion is interesting, but I'm worried about a functionality trade. One of the original reasons for the decision I made was to easily allow configuration of logging for the entire application in one place. I can see the argument for letting modules log differently, but I can't grok how to do that while still allowing the choice of how it works today. That is, all modules simply use Log, and the calling program does the configuration.

Besides, when I need that level of control, I'm probably already in the realm of wanting all that Log::Log4Perl provides anyhow, so I'd move to that point. Unless I'm missing something? I'd be open to suggestions on how I could have it both ways, in which case it would go on my todo list.

[Anonymous Monk]

You need more methods to implement important functionality!

Log->rolldown($stairs, { pairs => false } );
Log->rollover( Neighbour->dog() );
Log->compress(size=> $back);
Log->set_snackable(true);
Log->set_attributes ( big=>true, heavy=>true, wood=>true);
assert( $Log->virtues > $bad && $Log->virtues == GOOD );
Log->set_target_market( $everyone)
sub get { return new Log }

You may have to work out the copyrights from Blammo, Inc., however. :-)

[revdiablo]

Before any more downvoters take the AnonyPost seriously, see also: the original lyrics.

[dynamo]

My first thought is that the verbosity levels could use some constants in place of those 0,1,2,3s. Because that's the _only_ user unfriendly part I see in the whole API..

I'd also like to eventually see it accept a parameter in the use Log line with the filename etc.., where you can give it a custom subref with a single scalar as input and output, to reformat the data before output.

Looks good overall, nice job.