--- AnyEvent/lib/AnyEvent/Log.pm 2011/08/25 00:24:47 1.30 +++ AnyEvent/lib/AnyEvent/Log.pm 2012/04/09 02:25:48 1.59 @@ -8,12 +8,30 @@ 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!"; # never returns + AE::log fatal => "No config found, cannot continue!"; # never returns + AE::log alert => "The battery died!"; + AE::log crit => "The battery temperature is too hot!"; + AE::log error => "Division by zero attempted."; + AE::log warn => "Couldn't delete the file."; + AE::log note => "Wanted to create config, but config already exists."; + AE::log info => "File soandso successfully deleted."; + AE::log debug => "the function returned 3"; + AE::log trace => "going to call function abc"; -"Complex" uses (for speed sensitive code): +Log level overview: + + LVL NAME SYSLOG PERL NOTE + 1 fatal emerg exit system unusable, aborts program! + 2 alert failure in primary system + 3 critical crit failure in backup system + 4 error err die non-urgent program errors, a bug + 5 warn warning possible problem, not necessarily error + 6 note notice unusual conditions + 7 info normal messages, no action required + 8 debug debugging messages for development + 9 trace copious tracing output + +"Complex" uses (for speed sensitive code, e.g. trace/debug messages): use AnyEvent::Log; @@ -34,7 +52,7 @@ # regardless of (most) other settings $AnyEvent::Log::COLLECT->attach (new AnyEvent::Log::Ctx level => "critical", - log_to_syslog => 0, + log_to_syslog => "user", ); =head1 DESCRIPTION @@ -45,21 +63,25 @@ 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> (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: +Remember that the default verbosity level is C<4> (C), so only +errors and more important messages will be logged, unless you set +C to a higher number before starting your program +(C is recommended during development), or change the logging +level at runtime with something like: use AnyEvent::Log; - AnyEvent::Log::FILTER->level ("info"); + $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. +The module is also usable before AnyEvent itself is initialised, in which +case some of the functionality might be reduced. + +The amount of documentation might indicate otherwise, but the runtime part +of the module is still just below 300 lines of code. =head1 LOGGING LEVELS @@ -71,34 +93,44 @@ 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 + 1 fatal emerg exit system unusable, aborts program! + 2 alert failure in primary system + 3 critical crit failure in backup system + 4 error err die non-urgent program errors, a bug + 5 warn warning possible problem, not necessarily error + 6 note notice unusual conditions + 7 info normal messages, no action required + 8 debug debugging messages for development + 9 trace copious tracing output 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 :) +and the third one the "perl" name, suggesting (only!) that you log C +messages at C priority. The NOTE column tries to provide some +rationale on how to chose a logging level. + +As a rough guideline, levels 1..3 are primarily meant for users of the +program (admins, staff), and are the only ones logged to STDERR by +default. Levels 4..6 are meant for users and developers alike, while +levels 7..9 are usually meant for developers. + +You can normally only log a message once at highest priority level (C<1>, +C), because logging a fatal message will also quit the program - so +use it sparingly :) + +For example, a program that finds an unknown switch on the commandline +might well use a fatal logging level to tell users about it - the "system" +in this case would be the program, or module. 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. +or C - these are only valid for the methods that documented them. =head1 LOGGING FUNCTIONS -These functions allow you to log messages. They always use the caller's -package as a "logging context". Also, the main logging function C is -callable as C or C when the C module is -loaded. +The following functions allow you to log messages. They always use the +caller's package as a "logging context". Also, the main logging function, +C, is aliased to C and C when the C +module is loaded. =over 4 @@ -109,8 +141,12 @@ use Carp (); use POSIX (); +# layout of a context +# 0 1 2 3 4, 5 +# [$title, $level, %$slaves, &$logcb, &$fmtcb, $cap] + use AnyEvent (); BEGIN { AnyEvent::common_sense } -use AnyEvent::Util (); +#use AnyEvent::Util (); need to load this in a delayed fashion, as it uses AE::log our $VERSION = $AnyEvent::VERSION; @@ -150,7 +186,7 @@ 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. +For loglevel C, the program will abort. If only a C<$msg> is given, it is logged as-is. With extra C<@args>, the C<$msg> is interpreted as an sprintf format string. @@ -163,6 +199,9 @@ actually gets logged, which is useful if it is costly to create the message in the first place. +This function takes care of saving and restoring C<$!> and C<$@>, so you +don't have to. + Whether the given message will be logged depends on the maximum log level and the caller's package. The return value can be used to ensure that messages or not "lost" - for example, when L detects a @@ -205,10 +244,21 @@ trace => 9, ); -sub now () { time } +our $TIME_EXACT; + +sub exact_time($) { + $TIME_EXACT = shift; + *_ts = $AnyEvent::MODEL + ? $TIME_EXACT ? \&AE::now : \&AE::time + : sub () { $TIME_EXACT ? do { require Time::HiRes; Time::HiRes::time () } : time }; +} + +BEGIN { + exact_time 0; +} AnyEvent::post_detect { - *now = \&AE::now; + exact_time $TIME_EXACT; }; our @LEVEL2STR = qw(0 fatal alert crit error warn note info debug trace); @@ -228,6 +278,10 @@ join "", @res } +sub fatal_exit() { + exit 1; +} + sub _log { my ($ctx, $level, $format, @args) = @_; @@ -237,27 +291,40 @@ my $mask = 1 << $level; - my ($success, %seen, @ctx, $now, $fmt); + my ($success, %seen, @ctx, $now, @fmt); do { - # skip if masked - if ($ctx->[1] & $mask && !$seen{$ctx+0}++) { + # if !ref, then it's a level number + if (!ref $ctx) { + $level = $ctx; + } elsif ($ctx->[1] & $mask and !$seen{$ctx+0}++) { + # logging/recursing into this context + + # level cap + if ($ctx->[5] > $level) { + push @ctx, $level; # restore level when going up in tree + $level = $ctx->[5]; + } + + # log if log cb if ($ctx->[3]) { # logging target found + local ($!, $@); + # 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; + $now = _ts; }; # format msg my $str = $ctx->[4] ? $ctx->[4]($now, $_[0], $level, $format) - : ($fmt ||= _format $now, $_[0], $level, $format); + : ($fmt[$level] ||= _format $now, $_[0], $level, $format); $success = 1; @@ -270,7 +337,7 @@ } while $ctx = pop @ctx; - exit 1 if $level <= 1; + fatal_exit if $level <= 1; $success } @@ -281,8 +348,6 @@ @_; } -*AnyEvent::log = *AE::log = \&log; - =item $logger = AnyEvent::Log::logger $level[, \$enabled] Creates a code reference that, when called, acts as if the @@ -356,10 +421,11 @@ _reassess $logger+0; - my $guard = AnyEvent::Util::guard { + require AnyEvent::Util unless $AnyEvent::Util::VERSION; + my $guard = AnyEvent::Util::guard (sub { # "clean up" delete $LOGGER{$logger+0}; - }; + }); sub { $guard if 0; # keep guard alive, but don't cause runtime overhead @@ -375,6 +441,21 @@ @_ } +=item AnyEvent::Log::exact_time $on + +By default, C will use C, i.e. the cached +eventloop time, for the log timestamps. After calling this function with a +true value it will instead resort to C, i.e. fetch the current +time on each log message. This only makes a difference for event loops +that actually cache the time (such as L or L). + +This setting can be changed at any time by calling this function. + +Since C has to work even before the L has been +initialised, this switch will also decide whether to use C or +C when logging a message before L becomes +available. + =back =head1 LOGGING CONTEXTS @@ -503,6 +584,9 @@ =cut +our $ORIG_VERBOSE = $AnyEvent::VERBOSE; +$AnyEvent::VERBOSE = 9; + sub reset { # hard to kill complex data structures # we "recreate" all package loggers and reset the hierarchy @@ -515,13 +599,13 @@ @$_ = ($_->[0], (1 << 10) - 1 - 1) for $LOG, $FILTER, $COLLECT; - $LOG->slaves; + #$LOG->slaves; $LOG->title ('$AnyEvent::Log::LOG'); $LOG->log_to_warn; $FILTER->slaves ($LOG); $FILTER->title ('$AnyEvent::Log::FILTER'); - $FILTER->level ($AnyEvent::VERBOSE); + $FILTER->level ($ORIG_VERBOSE); $COLLECT->slaves ($FILTER); $COLLECT->title ('$AnyEvent::Log::COLLECT'); @@ -529,6 +613,14 @@ _reassess; } +# override AE::log/logger +*AnyEvent::log = *AE::log = \&log; +*AnyEvent::logger = *AE::logger = \&logger; + +# convert AnyEvent loggers to AnyEvent::Log loggers +$_->[0] = ctx $_->[0] # convert "pkg" to "ctx" + for values %LOGGER; + # create the default logger contexts $LOG = ctx undef; $FILTER = ctx undef; @@ -546,9 +638,6 @@ 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 @@ -645,6 +734,28 @@ Disables logging for the given levels, leaving all others unchanged. +=item $ctx->cap ($level) + +Caps the maximum priority to the given level, for all messages logged +to, or passing through, this context. That is, while this doesn't affect +whether a message is logged or passed on, the maximum priority of messages +will be limited to the specified level - messages with a higher priority +will be set to the specified priority. + +Another way to view this is that C<< ->level >> filters out messages with +a too low priority, while C<< ->cap >> modifies messages with a too high +priority. + +This is useful when different log targets have different interpretations +of priority. For example, for a specific command line program, a wrong +command line switch might well result in a C log message, while the +same message, logged to syslog, is likely I fatal to the system or +syslog facility as a whole, but more likely a mere C. + +This can be modeled by having a stderr logger that logs messages "as-is" +and a syslog logger that logs messages with a level cap of, say, C, +or, for truly system-critical components, actually C. + =cut sub _lvl_lst { @@ -655,6 +766,10 @@ } @_ } +sub _lvl { + $_[0] =~ /^(?:0|off|none)$/ ? 0 : (_lvl_lst $_[0])[-1] +} + our $NOP_CB = sub { 0 }; sub levels { @@ -667,9 +782,7 @@ sub level { my $ctx = shift; - my $lvl = $_[0] =~ /^(?:0|off|none)$/ ? 0 : (_lvl_lst $_[0])[-1]; - - $ctx->[1] = ((1 << $lvl) - 1) << 1; + $ctx->[1] = ((1 << &_lvl) - 1) << 1; AnyEvent::Log::_reassess; } @@ -687,6 +800,11 @@ AnyEvent::Log::_reassess; } +sub cap { + my $ctx = shift; + $ctx->[5] = &_lvl; +} + =back =head3 SLAVE CONTEXTS @@ -748,7 +866,7 @@ =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). @@ -783,12 +901,12 @@ 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 (object, not title), 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 reason, you want to use C to find out more baout the +If, for some reason, you want to use C to find out more about the logger then you should walk up the call stack until you are no longer inside the C package. @@ -802,7 +920,7 @@ }); Example: return an array reference with just the log values, and use -C to store the emssage in a database. +C to store the message in a database. $ctx->fmt_cb (sub { \@_ }); $ctx->log_cb (sub { @@ -824,7 +942,8 @@ =item $ctx->log_to_file ($path) -Sets the C to log to a file (by appending), unbuffered. +Sets the C to log to a file (by appending), unbuffered. The +function might return before the log file has been opened or created. =item $ctx->log_to_path ($path) @@ -836,12 +955,12 @@ calling C, the path should be absolute. Doesn't help with C, but hey... -=item $ctx->log_to_syslog ([$log_flags]) +=item $ctx->log_to_syslog ([$facility]) -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. +Logs all messages via L, mapping C to C and +all the others in the obvious way. If specified, then the C<$facility> is +used as the facility (C, C, C and so on). The default +facility is C. Note that this function also sets a C - the logging part requires an array reference with [$level, $str] as input. @@ -869,32 +988,104 @@ }); } +# this function is a good example of why threads are a must, +# simply for priority inversion. +sub _log_to_disk { + # eval'uating this at runtime saves 220kb rss - perl has become + # an insane memory waster. + eval q{ # poor man's autoloading {} + sub _log_to_disk { + my ($ctx, $path, $keepopen) = @_; + + my $fh; + my @queue; + my $delay; + my $disable; + + use AnyEvent::IO (); + + my $kick = sub { + undef $delay; + return unless @queue; + $delay = 1; + + # we pass $kick to $kick, so $kick itself doesn't keep a reference to $kick. + my $kick = shift; + + # write one or more messages + my $write = sub { + # we write as many messages as have been queued + my $data = join "", @queue; + @queue = (); + + AnyEvent::IO::aio_write $fh, $data, sub { + $disable = 1; + @_ + ? ($_[0] == length $data or AE::log 4 => "unable to write to logfile '$path': short write") + : AE::log 4 => "unable to write to logfile '$path': $!"; + undef $disable; + + if ($keepopen) { + $kick->($kick); + } else { + AnyEvent::IO::aio_close ($fh, sub { + undef $fh; + $kick->($kick); + }); + } + }; + }; + + if ($fh) { + $write->(); + } else { + AnyEvent::IO::aio_open + $path, + AnyEvent::IO::O_CREAT | AnyEvent::IO::O_WRONLY | AnyEvent::IO::O_APPEND, + 0666, + sub { + $fh = shift + or do { + $disable = 1; + AE::log 4 => "unable to open logfile '$path': $!"; + undef $disable; + return; + }; + + $write->(); + } + ; + } + }; + + $ctx->log_cb (sub { + return if $disable; + push @queue, shift; + $kick->($kick) unless $delay; + 0 + }); + + $kick->($kick) if $keepopen; # initial open + }; + }; + die if $@; + &_log_to_disk +} + sub log_to_file { my ($ctx, $path) = @_; - open my $fh, ">>", $path - or die "$path: $!"; - - $ctx->log_cb (sub { - syswrite $fh, shift; - 0 - }); + _log_to_disk $ctx, $path, 1; } sub log_to_path { my ($ctx, $path) = @_; - $ctx->log_cb (sub { - open my $fh, ">>", $path - or die "$path: $!"; - - syswrite $fh, shift; - 0 - }); + _log_to_disk $ctx, $path, 0; } sub log_to_syslog { - my ($ctx, $flags) = @_; + my ($ctx, $facility) = @_; require Sys::Syslog; @@ -905,10 +1096,12 @@ [$_[2], "($_[1][0]) $str"] }); + $facility ||= "user"; + $ctx->log_cb (sub { my $lvl = $_[0][0] < 9 ? $_[0][0] : 8; - Sys::Syslog::syslog ($flags | ($lvl - 1), $_) + Sys::Syslog::syslog ("$facility|" . ($lvl - 1), $_) for split /\n/, $_[0][1]; 0 @@ -928,6 +1121,10 @@ Same as C, but uses the given context as log context. +Example: log a message in the context of another package. + + (AnyEvent::Log::ctx "Other::Package")->log (warn => "heely bo"); + =item $logger = $ctx->logger ($level[, \$enabled]) Same as C, but uses the given context as log @@ -1014,7 +1211,7 @@ =item C or CI -Configured the context to log to syslog. If I is given, then it is +Configures the context to log to syslog. If I is given, then it is evaluated in the L package, so you could use: log=syslog=LOG_LOCAL0 @@ -1024,9 +1221,15 @@ Configures the context to not log anything by itself, which is the default. Same as C<< $ctx->log_cb (undef) >>. +=item CI + +Caps logging messages entering this context at the given level, i.e. +reduces the priority of messages with higher priority than this level. The +default is C<0> (or C), meaning the priority will not be touched. + =item C<0> or C -Sets the logging level of the context ot C<0>, i.e. all messages will be +Sets the logging level of the context to C<0>, i.e. all messages will be filtered out. =item C @@ -1066,7 +1269,7 @@ # or, more verbose filter=only,level,warn -=item C<1>..C<9>, a logging level name (C, C etc.) +=item C<1>..C<9> or a logging level name (C, C etc.) A numeric loglevel or the name of a loglevel will be interpreted according to the most recent C, C or C directive. By default, @@ -1074,13 +1277,13 @@ =item C<+>I -Adds/attaches the named context as slave to the context. +Attaches the named context as slave to the context. =item C<+> -A line C<+> clears the slave list form the context. Anonymous (C<%name>) -contexts have no slaves by default, but package contexts have the parent -context as slave by default. +A lone C<+> detaches all contexts, i.e. clears the slave list from the +context. Anonymous (C<%name>) contexts have no attached slaves by default, +but package contexts have the parent context as slave by default. Example: log messages from My::Module to a file, do not send them to the default log collector. @@ -1090,8 +1293,8 @@ =back Any character can be escaped by prefixing it with a C<\> (backslash), as -usual, so to log to a file containing a comma, colon, backslash and space in the -filename, you would do this: +usual, so to log to a file containing a comma, colon, backslash and some +spaces in the filename, you would do this: PERL_ANYEVENT_LOG='log=file=/some\ \:file\ with\,\ \\-escapes' @@ -1119,7 +1322,7 @@ $_[0] eq "log" ? $LOG : $_[0] eq "filter" ? $FILTER : $_[0] eq "collect" ? $COLLECT - : $_[0] =~ /^%(.+)$/ ? ($anon{$1} ||= ctx undef) + : $_[0] =~ /^%(.+)$/ ? ($anon{$1} ||= do { my $ctx = ctx undef; $ctx->[0] = $_[0]; $ctx }) : $_[0] =~ /^(.*?)(?:::)?$/ ? ctx "$1" # egad :/ : die # never reached? }; @@ -1135,8 +1338,9 @@ if ($_ eq "stderr" ) { $ctx->log_to_warn; } elsif (/^file=(.+)/ ) { $ctx->log_to_file ("$1"); } elsif (/^path=(.+)/ ) { $ctx->log_to_path ("$1"); - } elsif (/syslog(?:=(.*))?/ ) { require Sys::Syslog; $ctx->log_to_syslog (eval "package Sys::Syslog; $1"); + } elsif (/^syslog(?:=(.*))?/ ) { require Sys::Syslog; $ctx->log_to_syslog ("$1"); } elsif ($_ eq "nolog" ) { $ctx->log_cb (undef); + } elsif (/^cap=(.+)/ ) { $ctx->cap ("$1"); } elsif (/^\+(.+)$/ ) { $ctx->attach ($pkg->("$1")); } elsif ($_ eq "+" ) { $ctx->slaves; } elsif ($_ eq "off" or $_ eq "0") { $ctx->level (0); @@ -1163,8 +1367,6 @@ } } -1; - =head1 EXAMPLES This section shows some common configurations, both as code, and as @@ -1198,7 +1400,7 @@ it is attached to the default context which is invoked I global filtering. - $AnyEvent::Log::FILTER->attach + $AnyEvent::Log::FILTER->attach ( new AnyEvent::Log::Ctx log_to_file => $path); PERL_ANYEVENT_LOG=filter=+%filelogger:%filelogger=file=/some/path @@ -1214,6 +1416,23 @@ In both cases, messages are still written to STDERR. +=item Additionally log all messages with C and higher priority to +C, but cap at C. + +This logs all messages to the default log target, but also logs messages +with priority C or higher (and not filtered otherwise) to syslog +facility C. Messages with priority higher than C will be +logged with level C. + + $AnyEvent::Log::LOG->attach ( + new AnyEvent::Log::Ctx + level => "warn", + cap => "error", + syslog => "user", + ); + + PERL_ANYEVENT_LOG=log=+%syslog:%syslog=warn,cap=error,syslog + =item Write trace messages (only) from L to the default logging target(s). Attach the C<$AnyEvent::Log::LOG> context to the C @@ -1233,7 +1452,9 @@ =head1 AUTHOR Marc Lehmann - http://home.schmorp.de/ + http://anyevent.schmorp.de =cut +1 +