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:
- An interface that doesn't get in the way of "real" code.
- Automagical logging of die/warn events
- Easy configuration, in as few lines of code as possible.
- Pure perl
- 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
- The name is bad. Really bad. I know that.
- 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.
- 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.
- 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__
Log ($Revision: 1.9 $) - Logging package for info/warn/die/debug/trace
top
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
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
- 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
- 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
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
Re: RFC: A simple and badly-named logging module
by YuckFoo (Abbot) on Feb 17, 2006 at 21:56 UTC
|
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
| [reply] [d/l] [select] |
|
I've put most of these on my todo list, excellent suggestions! Some points...
- I agree that the TDIWX set is better than the longer versions, though I think I might make that configurable.
- 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.
- PID logging is a good idea, but I will be keeping the sequence numbers as an option (appended to the PID).
- 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.
| [reply] [d/l] [select] |
Re: RFC: A simple and badly-named logging module
by xdg (Monsignor) on Feb 18, 2006 at 01:47 UTC
|
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.
-xdg
Code written by xdg and posted on PerlMonks is public domain. It is provided as is with no warranties, express or implied, of any kind. Posted code may not have been tested. Use of posted code is at your own risk.
| [reply] [d/l] [select] |
|
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.
| [reply] [d/l] [select] |
Re: RFC: A simple and badly-named logging module
by Anonymous Monk on Feb 17, 2006 at 19:54 UTC
|
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. :-) | [reply] [d/l] |
|
| [reply] |
Re: RFC: A simple and badly-named logging module
by dynamo (Chaplain) on Feb 17, 2006 at 21:30 UTC
|
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.
| [reply] |
|
|