--- AnyEvent/lib/AnyEvent/Log.pm 2011/08/19 21:17:08 1.10 +++ AnyEvent/lib/AnyEvent/Log.pm 2011/08/21 03:25:47 1.25 @@ -4,15 +4,17 @@ =head1 SYNOPSIS - # simple use +Simple uses: + use AnyEvent; AE::log debug => "hit my knee"; AE::log warn => "it's a bit too hot"; AE::log error => "the flag was false!"; - AE::log fatal => "the bit toggled! run!"; + AE::log fatal => "the bit toggled! run!"; # never returns + +"Complex" uses (for speed sensitive code): - # "complex" use use AnyEvent::Log; my $tracer = AnyEvent::Log::logger trace => \$my $trace; @@ -20,23 +22,20 @@ $tracer->("i am here") if $trace; $tracer->(sub { "lots of data: " . Dumper $self }) if $trace; - # configuration - - # set logging for this package to maximum - AnyEvent::Log::ctx->level ("all"); - - # set logging globally to anything below debug - (AnyEvent::Log::ctx "")->level ("notice"); +Configuration (also look at the EXAMPLES section): - # see also EXAMPLES, below + # set logging for the current package to errors and higher only + AnyEvent::Log::ctx->level ("error"); - # disable logging for package "AnyEvent" and all packages below it - AnyEvent->AnyEvent::Log::ctx->level (0); + # set logging level to suppress anything below "notice" + $AnyEvent::Log::FILTER->level ("notice"); - # log everything below debug to a file, for the whole program - my $ctx = AnyEvent::Log::ctx; - $ctx->log_cb (sub { print FILE shift; 0 }); - (AnyEvent::Log::ctx "")->add ($ctx); + # send all critical and higher priority messages to syslog, + # regardless of (most) other settings + $AnyEvent::Log::COLLECT->attach (new AnyEvent::Log::Ctx + level => "critical", + log_to_syslog => 0, + ); =head1 DESCRIPTION @@ -46,23 +45,58 @@ module more or less exposes the mechanism, with some extra spiff to allow using it from other modules as well. -Remember that the default verbosity level is C<0>, so nothing will be -logged, ever, unless you set C to a higher number -before starting your program, or change the logging level at runtime wiht +Remember that the default verbosity level is C<0> (C), so nothing +will be logged, unless you set C to a higher number +before starting your program, or change the logging level at runtime with something like: - use AnyEvent; - (AnyEvent::Log::ctx "")->level ("info"); + use AnyEvent::Log; + AnyEvent::Log::FILTER->level ("info"); The design goal behind this module was to keep it simple (and small), but make it powerful enough to be potentially useful for any module, and extensive enough for the most common tasks, such as logging to multiple targets, or being able to log into a database. +The amount of documentation might indicate otherwise, but the module is +still just below 300 lines of code. + +=head1 LOGGING LEVELS + +Logging levels in this module range from C<1> (highest priority) to C<9> +(lowest priority). Note that the lowest numerical value is the highest +priority, so when this document says "higher priority" it means "lower +numerical value". + +Instead of specifying levels by name you can also specify them by aliases: + + LVL NAME SYSLOG PERL NOTE + 1 fatal emerg exit aborts program! + 2 alert + 3 critical crit + 4 error err die + 5 warn warning + 6 note notice + 7 info + 8 debug + 9 trace + +As you can see, some logging levels have multiple aliases - the first one +is the "official" name, the second one the "syslog" name (if it differs) +and the third one the "perl" name, suggesting that you log C messages +at C priority. + +You can normally only log a single message at highest priority level +(C<1>, C), because logging a fatal message will also quit the +program - so use it sparingly :) + +Some methods also offer some extra levels, such as C<0>, C, C +or C - these are only valid in the methods they are documented for. + =head1 LOGGING FUNCTIONS These functions allow you to log messages. They always use the caller's -package as a "logging module/source". Also, the main logging function is +package as a "logging context". Also, the main logging function C is callable as C or C when the C module is loaded. @@ -78,6 +112,10 @@ use AnyEvent (); BEGIN { AnyEvent::common_sense } use AnyEvent::Util (); +our $VERSION = $AnyEvent::VERSION; + +our ($COLLECT, $FILTER, $LOG); + our ($now_int, $now_str1, $now_str2); # Format Time, not public - yet? @@ -91,27 +129,26 @@ "$now_str1$f$now_str2" } -our %CTX; # all logging contexts +our %CTX; # all package contexts # creates a default package context object for the given package sub _pkg_ctx($) { my $ctx = bless [$_[0], (1 << 10) - 1 - 1, {}], "AnyEvent::Log::Ctx"; # link "parent" package - my $pkg = $_[0] =~ /^(.+)::/ ? $1 : ""; + my $parent = $_[0] =~ /^(.+)::/ + ? $CTX{$1} ||= &_pkg_ctx ("$1") + : $COLLECT; - $pkg = $CTX{$pkg} ||= &_pkg_ctx ($pkg); - $ctx->[2]{$pkg+0} = $pkg; + $ctx->[2]{$parent+0} = $parent; $ctx } =item AnyEvent::Log::log $level, $msg[, @args] -Requests logging of the given C<$msg> with the given log level (1..9). -You can also use the following strings as log level: C (1), -C (2), C (3), C (4), C (5), C (6), -C (7), C (8), C (9). +Requests logging of the given C<$msg> with the given log level, and +returns true if the message was logged I. For C log levels, the program will abort. @@ -127,14 +164,17 @@ message in the first place. Whether the given message will be logged depends on the maximum log level -and the caller's package. +and the caller's package. The return value can be used to ensure that +messages or not "lost" - for example, when L detects a +runtime error it tries to log it at C level, but if that message is +lost it simply uses warn. Note that you can (and should) call this function as C or C, without C-ing this module if possible (i.e. you don't need any additional functionality), as those functions will load the logging module on demand only. They are also much shorter to write. -Also, if you otpionally generate a lot of debug messages (such as when +Also, if you optionally generate a lot of debug messages (such as when tracing some code), you should look into using a logger callback and a boolean enabler (see C, below). @@ -154,10 +194,10 @@ # also allow syslog equivalent names our %STR2LEVEL = ( - fatal => 1, emerg => 1, + fatal => 1, emerg => 1, exit => 1, alert => 2, critical => 3, crit => 3, - error => 4, err => 4, + error => 4, err => 4, die => 4, warn => 5, warning => 5, note => 6, notice => 6, info => 7, @@ -175,12 +215,14 @@ # time, ctx, level, msg sub _format($$$$) { - my $pfx = ft $_[0]; + my $ts = ft $_[0]; + my $ct = " "; + my @res; for (split /\n/, sprintf "%-5s %s: %s", $LEVEL2STR[$_[2]], $_[1][0], $_[3]) { - push @res, "$pfx $_\n"; - $pfx = "\t"; + push @res, "$ts$ct$_\n"; + $ct = " + "; } join "", @res @@ -189,41 +231,48 @@ sub _log { my ($ctx, $level, $format, @args) = @_; - $level = $level > 0 && $level <= 9 ? $level+0 : $STR2LEVEL{$level} || Carp::croak "$level: not a valid logging level, caught"; + $level = $level > 0 && $level <= 9 + ? $level+0 + : $STR2LEVEL{$level} || Carp::croak "$level: not a valid logging level, caught"; my $mask = 1 << $level; - my (@ctx, $now, $fmt); - - do { - # skip if masked - next unless $ctx->[1] & $mask; - - if ($ctx->[3]) { - # logging target found - - # now get raw message, unless we have it already - unless ($now) { - $format = $format->() if ref $format; - $format = sprintf $format, @args if @args; - $format =~ s/\n$//; - $now = AE::now; - }; - - # format msg - my $str = $ctx->[4] - ? $ctx->[4]($now, $_[0], $level, $format) - : $fmt ||= _format $now, $_[0], $level, $format; + my ($success, %seen, @ctx, $now, $fmt); - $ctx->[3]($str) - and next; + do + { + # skip if masked + if ($ctx->[1] & $mask && !$seen{$ctx+0}++) { + if ($ctx->[3]) { + # logging target found + + # now get raw message, unless we have it already + unless ($now) { + $format = $format->() if ref $format; + $format = sprintf $format, @args if @args; + $format =~ s/\n$//; + $now = AE::now; + }; + + # format msg + my $str = $ctx->[4] + ? $ctx->[4]($now, $_[0], $level, $format) + : ($fmt ||= _format $now, $_[0], $level, $format); + + $success = 1; + + $ctx->[3]($str) + or push @ctx, values %{ $ctx->[2] }; # not consumed - propagate + } else { + push @ctx, values %{ $ctx->[2] }; # not masked - propagate + } + } } - - # not masked, not consume - propagate to parent contexts - push @ctx, values %{ $ctx->[2] }; - } while $ctx = pop @ctx; + while $ctx = pop @ctx; exit 1 if $level <= 1; + + $success } sub log($$;@) { @@ -237,7 +286,7 @@ =item $logger = AnyEvent::Log::logger $level[, \$enabled] Creates a code reference that, when called, acts as if the -C function was called at this point with the givne +C function was called at this point with the given level. C<$logger> is passed a C<$msg> and optional C<@args>, just as with the C function: @@ -272,39 +321,33 @@ $debug and $debug_log->("123"); -Note: currently the enabled var is always true - that will be fixed in a -future version :) - =cut our %LOGGER; # re-assess logging status for all loggers sub _reassess { + local $SIG{__DIE__}; + my $die = sub { die }; + for (@_ ? $LOGGER{$_[0]} : values %LOGGER) { my ($ctx, $level, $renabled) = @$_; - # to detetc whether a message would be logged, we # actually - # try to log one and die. this isn't # fast, but we can be + # to detect whether a message would be logged, we actually + # try to log one and die. this isn't fast, but we can be # sure that the logging decision is correct :) $$renabled = !eval { - local $SIG{__DIE__}; - - _log $ctx, $level, sub { die }; + _log $ctx, $level, $die; 1 }; - - $$renabled = 1; # TODO } } -sub _logger($;$) { +sub _logger { my ($ctx, $level, $renabled) = @_; - $renabled ||= \my $enabled; - $$renabled = 1; my $logger = [$ctx, $level, $renabled]; @@ -353,11 +396,15 @@ actually logging the formatted message and telling C whether it has consumed the message, or whether it should be propagated). -For propagation, a context can have any number of attached I. Any message that is neither masked by the logging mask nor -masked by the logging callback returning true will be passed to all parent +masked by the logging callback returning true will be passed to all slave contexts. +Each call to a logging function will log the message at most once per +context, so it does not matter (much) if there are cycles or if the +message can arrive at the same context via multiple paths. + =head2 DEFAULTS By default, all logging contexts have an full set of log levels ("all"), a @@ -365,27 +412,58 @@ Package contexts have the package name as logging title by default. -They have exactly one parent - the context of the "parent" package. The +They have exactly one slave - the context of the "parent" package. The parent package is simply defined to be the package name without the last component, i.e. C becomes C, -and C becomes the empty string. +and C becomes ... C<$AnyEvent::Log::COLLECT> which is the +exception of the rule - just like the "parent" of any single-component +package name in Perl is C
, the default slave of any top-level +package context is C<$AnyEvent::Log::COLLECT>. -Since perl packages form only an approximate hierarchy, this parent +Since perl packages form only an approximate hierarchy, this slave context can of course be removed. -All other (anonymous) contexts have no parents and an empty title by +All other (anonymous) contexts have no slaves and an empty title by default. -When the module is first loaded, it configures the root context (the one -with the empty string) to simply dump all log messages to C, -and sets it's log level set to all levels up to the one specified by -C<$ENV{PERL_ANYEVENT_VERBOSE}>. +When the module is loaded it creates the C<$AnyEvent::Log::LOG> logging +context that simply logs everything via C, without propagating +anything anywhere by default. The purpose of this context is to provide +a convenient place to override the global logging target or to attach +additional log targets. It's not meant for filtering. + +It then creates the C<$AnyEvent::Log::FILTER> context whose +purpose is to suppress all messages with priority higher +than C<$ENV{PERL_ANYEVENT_VERBOSE}>. It then attached the +C<$AnyEvent::Log::LOG> context to it. The purpose of the filter context +is to simply provide filtering according to some global log level. + +Finally it creates the top-level package context C<$AnyEvent::Log::COLLECT> +and attaches the C<$AnyEvent::Log::FILTER> context to it, but otherwise +leaves it at default config. Its purpose is simply to collect all log +messages system-wide. + +The hierarchy is then: + + any package, eventually -> $COLLECT -> $FILTER -> $LOG The effect of all this is that log messages, by default, wander up to the -root context and will be logged to STDERR if their log level is less than -or equal to C<$ENV{PERL_ANYEVENT_VERBOSE}>. +C<$AnyEvent::Log::COLLECT> context where all messages normally end up, +from there to C<$AnyEvent::Log::FILTER> where log messages with lower +priority then C<$ENV{PERL_ANYEVENT_VERBOSE}> will be filtered out and then +to the C<$AnyEvent::Log::LOG> context to be passed to C. + +This makes it easy to set a global logging level (by modifying $FILTER), +but still allow other contexts to send, for example, their debug and trace +messages to the $LOG target despite the global logging level, or to attach +additional log targets that log messages, regardless of the global logging +level. + +It also makes it easy to modify the default warn-logger ($LOG) to +something that logs to a file, or to attach additional logging targets +(such as loggign to a file) by attaching it to $FILTER. -=head2 CREATING/FINDING A CONTEXT +=head2 CREATING/FINDING/DESTROYING CONTEXTS =over 4 @@ -413,27 +491,104 @@ : bless [undef, (1 << 10) - 1 - 1], "AnyEvent::Log::Ctx" } -# create default root context -{ - my $root = ctx undef; - $root->[0] = ""; - $root->title ("default"); - $root->level ($AnyEvent::VERBOSE); undef $AnyEvent::VERBOSE; - $root->log_cb (sub { - print STDERR shift; +=item AnyEvent::Log::reset + +Resets all package contexts and recreates the default hierarchy if +necessary, i.e. resets the logging subsystem to defaults, as much as +possible. This process keeps references to contexts held by other parts of +the program intact. + +This can be used to implement config-file (re-)loading: before loading a +configuration, reset all contexts. + +=cut + +sub reset { + # hard to kill complex data structures + # we "recreate" all package loggers and reset the hierarchy + while (my ($k, $v) = each %CTX) { + @$v = ($k, (1 << 10) - 1 - 1, { }); + + $v->attach ($k =~ /^(.+)::/ ? $CTX{$1} : $AnyEvent::Log::COLLECT); + } + + @$_ = ($_->[0], (1 << 10) - 1 - 1) + for $LOG, $FILTER, $COLLECT; + + $LOG->slaves; + $LOG->title ('$AnyEvent::Log::LOG'); + $LOG->log_cb (sub { + warn shift; 0 }); - $CTX{""} = $root; -} + + $FILTER->slaves ($LOG); + $FILTER->title ('$AnyEvent::Log::FILTER'); + $FILTER->level ($AnyEvent::VERBOSE); + + $COLLECT->slaves ($FILTER); + $COLLECT->title ('$AnyEvent::Log::COLLECT'); + + _reassess; +} + +# create the default logger contexts +$LOG = ctx undef; +$FILTER = ctx undef; +$COLLECT = ctx undef; + +AnyEvent::Log::reset; + +# hello, CPAN, please catch me +package AnyEvent::Log::LOG; +package AE::Log::LOG; +package AnyEvent::Log::FILTER; +package AE::Log::FILTER; +package AnyEvent::Log::COLLECT; +package AE::Log::COLLECT; + +package AnyEvent::Log::Ctx; + +# 0 1 2 3 4 +# [$title, $level, %$slaves, &$logcb, &$fmtcb] + +=item $ctx = new AnyEvent::Log::Ctx methodname => param... + +This is a convenience constructor that makes it simpler to construct +anonymous logging contexts. + +Each key-value pair results in an invocation of the method of the same +name as the key with the value as parameter, unless the value is an +arrayref, in which case it calls the method with the contents of the +array. The methods are called in the same order as specified. + +Example: create a new logging context and set both the default logging +level, some slave contexts and a logging callback. + + $ctx = new AnyEvent::Log::Ctx + title => "dubious messages", + level => "error", + log_cb => sub { print STDOUT shift; 0 }, + slaves => [$ctx1, $ctx, $ctx2], + ; =back =cut -package AnyEvent::Log::Ctx; +sub new { + my $class = shift; + + my $ctx = AnyEvent::Log::ctx undef; + + while (@_) { + my ($k, $v) = splice @_, 0, 2; + $ctx->$k (ref $v eq "ARRAY" ? @$v : $v); + } + + bless $ctx, $class # do we really support subclassing, hmm? +} -# 0 1 2 3 4 -# [$title, $level, %$parents, &$logcb, &$fmtcb] =head2 CONFIGURING A LOG CONTEXT @@ -537,30 +692,34 @@ =back -=head3 PARENT CONTEXTS +=head3 SLAVE CONTEXTS The following methods attach and detach another logging context to a logging context. -Log messages are propagated to all parent contexts, unless the logging +Log messages are propagated to all slave contexts, unless the logging callback consumes the message. =over 4 =item $ctx->attach ($ctx2[, $ctx3...]) -Attaches the given contexts as parents to this context. It is not an error +Attaches the given contexts as slaves to this context. It is not an error to add a context twice (the second add will be ignored). A context can be specified either as package name or as a context object. =item $ctx->detach ($ctx2[, $ctx3...]) -Removes the given parents from this context - it's not an error to attempt +Removes the given slaves from this context - it's not an error to attempt to remove a context that hasn't been added. A context can be specified either as package name or as a context object. +=item $ctx->slaves ($ctx2[, $ctx3...]) + +Replaces all slaves attached to this context by the ones given. + =cut sub attach { @@ -577,18 +736,22 @@ for map { AnyEvent::Log::ctx $_ } @_; } +sub slaves { + undef $_[0][2]; + &attach; +} + =back -=head3 MESSAGE LOGGING +=head3 LOG TARGETS The following methods configure how the logging context actually does the logging (which consists of formatting the message and printing it or -whatever it wants to do with it) and also allows you to log messages -directly to a context, without going via your package context. +whatever it wants to do with it). =over 4 -=item $ctx->log_cb ($cb->($str)) +=item $ctx->log_cb ($cb->($str) Replaces the logging callback on the context (C disables the logging callback). @@ -599,7 +762,7 @@ It also has to return true iff it has consumed the log message, and false if it hasn't. Consuming a message means that it will not be sent to any -parent context. When in doubt, return C<0> from your logging callback. +slave context. When in doubt, return C<0> from your logging callback. Example: a very simple logging callback, simply dump the message to STDOUT and do not consume it. @@ -617,15 +780,20 @@ $ctx->levels ("debug", "trace"); $ctx->log_cb (sub { 1 }); # do not log, but eat debug and trace messages -=item $ctx->fmt_cb ($fmt_cb->($timestamp, $ctx, $level, $message)) +=item $ctx->fmt_cb ($fmt_cb->($timestamp, $orig_ctx, $level, $message)) Replaces the formatting callback on the context (C restores the default formatter). The callback is passed the (possibly fractional) timestamp, the original -logging context, the (numeric) logging level and the raw message string and needs to -return a formatted log message. In most cases this will be a string, but -it could just as well be an array reference that just stores the values. +logging context, the (numeric) logging level and the raw message string +and needs to return a formatted log message. In most cases this will be a +string, but it could just as well be an array reference that just stores +the values. + +If, for some reaosn, you want to use C to find out more baout the +logger then you should walk up the call stack until you are no longer +inside the C package. Example: format just the raw message, with numeric log level in angle brackets. @@ -652,6 +820,26 @@ 0 }); +=item $ctx->log_to_file ($path) + +Sets the C to log to a file (by appending), unbuffered. + +=item $ctx->log_to_path ($path) + +Same as C<< ->log_to_file >>, but opens the file for each message. This +is much slower, but allows you to change/move/rename/delete the file at +basically any time. + +=item $ctx->log_to_syslog ([$log_flags]) + +Logs all messages via L, mapping C to C and all +the others in the obvious way. If specified, then the C<$log_flags> are +simply or'ed onto the priority argument and can contain any C +flags valid for Sys::Syslog::syslog, except for the priority levels. + +Note that this function also sets a C - the logging part requires +an array reference with [$level, $str] as input. + =cut sub log_cb { @@ -666,6 +854,61 @@ $ctx->[4] = $cb; } +sub log_to_file { + my ($ctx, $path) = @_; + + open my $fh, ">>", $path + or die "$path: $!"; + + $ctx->log_cb (sub { + syswrite $fh, shift; + 0 + }); +} + +sub log_to_file { + my ($ctx, $path) = @_; + + $ctx->log_cb (sub { + open my $fh, ">>", $path + or die "$path: $!"; + + syswrite $fh, shift; + 0 + }); +} + +sub log_to_syslog { + my ($ctx, $flags) = @_; + + require Sys::Syslog; + + $ctx->fmt_cb (sub { + my $str = $_[3]; + $str =~ s/\n(?=.)/\n+ /g; + + [$_[2], "($_[1][0]) $str"] + }); + + $ctx->log_cb (sub { + my $lvl = $_[0][0] < 9 ? $_[0][0] : 8; + + Sys::Syslog::syslog ($flags | ($lvl - 1), $_) + for split /\n/, $_[0][1]; + + 0 + }); +} + +=back + +=head3 MESSAGE LOGGING + +These methods allow you to log messages directly to a context, without +going via your package context. + +=over 4 + =item $ctx->log ($level, $msg[, @params]) Same as C, but uses the given context as log context. @@ -684,6 +927,59 @@ =back +=head1 EXAMPLES + +This section shows some common configurations. + +=over 4 + +=item Setting the global logging level. + +Either put PERL_ANYEVENT_VERBOSE= into your environment before +running your program, or modify the log level of the root context: + + PERL_ANYEVENT_VERBOSE=5 ./myprog + + $AnyEvent::Log::FILTER->level ("warn"); + +=item Append all messages to a file instead of sending them to STDERR. + +This is affected by the global logging level. + + $AnyEvent::Log::LOG->log_to_file ($path); (sub { + +=item Write all messages with priority C and higher to a file. + +This writes them only when the global logging level allows it, because +it is attached to the default context which is invoked I global +filtering. + + $AnyEvent::Log::FILTER->attach + new AnyEvent::Log::Ctx log_to_file => $path); + +This writes them regardless of the global logging level, because it is +attached to the toplevel context, which receives all messages I +the global filtering. + + $AnyEvent::Log::COLLECT->attach ( + new AnyEvent::Log::Ctx log_to_file => $path); + +In both cases, messages are still written to STDERR. + +=item Write trace messages (only) from L to the default logging target(s). + +Attach the C<$AnyEvent::Log::LOG> context to the C +context - this simply circumvents the global filtering for trace messages. + + my $debug = AnyEvent::Debug->AnyEvent::Log::ctx; + $debug->attach ($AnyEvent::Log::LOG); + +This of course works for any package, not just L, but +assumes the log level for AnyEvent::Debug hasn't been changed from the +default. + +=back + =head1 AUTHOR Marc Lehmann