[ViewVC] Diff of: cvs/AnyEvent/lib/AnyEvent/Log.pm

Comparing AnyEvent/lib/AnyEvent/Log.pm (file contents):
Revision 1.36 by root, Thu Aug 25 05:39:47 2011 UTC vs.
Revision 1.45 by root, Sun Oct 2 00:42:04 2011 UTC

 Simple uses:
    use AnyEvent;
-   AE::log debug => "hit my knee";
+   AE::log trace => "going to call function abc";
-   AE::log warn  => "it's a bit too hot";
+   AE::log debug => "the function returned 3";
-   AE::log error => "the flag was false!";
+   AE::log info  => "file soandso successfully deleted";
-   AE::log fatal => "the bit toggled! run!"; # never returns
+   AE::log note  => "wanted to create config, but config was alraedy created";
+   AE::log warn  => "couldn't delete the file";
+   AE::log error => "failed to retrieve data";
+   AE::log crit  => "the battery temperature is too hot";
+   AE::log alert => "the battery died";
+   AE::log fatal => "no config found, cannot continue"; # never returns
+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):
+"Complex" uses (for speed sensitive code, e.g. trace/debug messages):
    use AnyEvent::Log;
    my $tracer = AnyEvent::Log::logger trace => \$my $trace;
    # 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,
+      log_to_syslog => "user",
    );
 =head1 DESCRIPTION
 This module implements a relatively simple "logging framework". It doesn't
 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!
+    1  fatal     emerg    exit  system unusable, aborts program!
-   2   alert
+    2  alert                    failure in primary system
-   3   critical  crit
+    3  critical  crit           failure in backup system
-   4   error     err      die
+    4  error     err      die   non-urgent program errors, a bug
-   5   warn      warning
+    5  warn      warning        possible problem, not necessarily error
-   6   note      notice
+    6  note      notice         unusual conditions
-   7   info
+    7  info                     normal messages, no action required
-   8   debug
+    8  debug                    debugging messages for development
-   9   trace
+    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<die> messages
+and the third one the "perl" name, suggesting (only!) that you log C<die>
-at C<error> priority.
+messages at C<error> 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 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 single message at highest priority level
 (C<1>, C<fatal>), because logging a fatal message will also quit the
 program - so use it sparingly :)
 package AnyEvent::Log;
 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;
 our ($COLLECT, $FILTER, $LOG);
 =item AnyEvent::Log::log $level, $msg[, @args]
 Requests logging of the given C<$msg> with the given log level, and
 returns true if the message was logged I<somewhere>.
-For C<fatal> log levels, the program will abort.
+For loglevel C<fatal>, 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.
 The C<$msg> should not end with C<\n>, but may if that is convenient for
    info     => 7,
    debug    => 8,
    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);
 # time, ctx, level, msg
    }
    join "", @res
 }
+sub fatal_exit() {
+   exit 1;
+}
 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";
    my $mask = 1 << $level;
-   my ($success, %seen, @ctx, $now, $fmt);
+   my ($success, %seen, @ctx, $now, @fmt);
    do
       {
-         # skip if masked
+         # if !ref, then it's a level number
+         if (!ref $ctx) {
+            $level = $ctx;
-         if ($ctx->[1] & $mask && !$seen{$ctx+0}++) {
+         } 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
                # 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 = 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;
                $ctx->[3]($str)
                   or push @ctx, values %{ $ctx->[2] }; # not consumed - propagate
             }
          }
       }
    while $ctx = pop @ctx;
-   exit 1 if $level <= 1;
+   fatal_exit if $level <= 1;
    $success
 }
 sub log($$;@) {
    _log
       $CTX{ (caller)[0] } ||= _pkg_ctx +(caller)[0],
       @_;
 }
-*AnyEvent::log = *AE::log = \&log;
 =item $logger = AnyEvent::Log::logger $level[, \$enabled]
 Creates a code reference that, when called, acts as if the
 C<AnyEvent::Log::log> function was called at this point with the given
 level. C<$logger> is passed a C<$msg> and optional C<@args>, just as with
    $LOGGER{$logger+0} = $logger;
    _reassess $logger+0;
+   require AnyEvent::Util unless $AnyEvent::Util::VERSION;
-   my $guard = AnyEvent::Util::guard {
+   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
       _log $ctx, $level, @_
 sub logger($;$) {
    _logger
       $CTX{ (caller)[0] } ||= _pkg_ctx +(caller)[0],
       @_
 }
+=item AnyEvent::Log::exact_time $on
+By default, C<AnyEvent::Log> will use C<AE::now>, i.e. the cached
+eventloop time, for the log timestamps. After calling this function with a
+true value it will instead resort to C<AE::time>, 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<EV> or L<AnyEvent::Loop>).
+This setting can be changed at any time by calling this function.
+Since C<AnyEvent::Log> has to work even before the L<AnyEvent> has been
+initialised, this switch will also decide whether to use C<CORE::time> or
+C<Time::HiRes::time> when logging a message before L<AnyEvent> becomes
+available.
 =back
 =head1 LOGGING CONTEXTS
 This can be used to implement config-file (re-)loading: before loading a
 configuration, reset all contexts.
 =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
    while (my ($k, $v) = each %CTX) {
       @$v = ($k, (1 << 10) - 1 - 1, { });
    $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');
    _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;
 $COLLECT = ctx undef;
 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.
 =item $ctx->disable ($level[, $level...])
 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<fatal> log message, while the
+same message, logged to syslog, is likely I<not> fatal to the system or
+syslog facility as a whole, but more likely a mere C<error>.
+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<error>,
+or, for truly system-critical components, actually C<critical>.
 =cut
 sub _lvl_lst {
    map {
       $_ > 0 && $_ <= 9 ? $_+0
       : $_ eq "all"     ? (1 .. 9)
       : $STR2LEVEL{$_} || Carp::croak "$_: not a valid logging level, caught"
    } @_
 }
+sub _lvl {
+   $_[0] =~ /^(?:0|off|none)$/ ? 0 : (_lvl_lst $_[0])[-1]
+}
 our $NOP_CB = sub { 0 };
 sub levels {
    my $ctx = shift;
    $ctx->[1] = 0;
    AnyEvent::Log::_reassess;
 }
 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;
 }
 sub enable {
    my $ctx = shift;
    $ctx->[1] &= ~(1 << $_)
       for &_lvl_lst;
    AnyEvent::Log::_reassess;
 }
+sub cap {
+   my $ctx = shift;
+   $ctx->[5] = &_lvl;
+}
 =back
 =head3 SLAVE CONTEXTS
 The following methods attach and detach another logging context to a
 Needless(?) to say, if you do not want to be bitten by some evil person
 calling C<chdir>, the path should be absolute. Doesn't help with
 C<chroot>, but hey...
-=item $ctx->log_to_syslog ([$log_flags])
+=item $ctx->log_to_syslog ([$facility])
-Logs all messages via L<Sys::Syslog>, mapping C<trace> to C<debug> and all
+Logs all messages via L<Sys::Syslog>, mapping C<trace> to C<debug> and
-the others in the obvious way. If specified, then the C<$log_flags> are
+all the others in the obvious way. If specified, then the C<$facility> is
-simply or'ed onto the priority argument and can contain any C<LOG_xxx>
+used as the facility (C<user>, C<auth>, C<local0> and so on). The default
-flags valid for Sys::Syslog::syslog, except for the priority levels.
+facility is C<user>.
 Note that this function also sets a C<fmt_cb> - the logging part requires
 an array reference with [$level, $str] as input.
 =cut
       0
    });
 }
 sub log_to_syslog {
-   my ($ctx, $flags) = @_;
+   my ($ctx, $facility) = @_;
    require Sys::Syslog;
    $ctx->fmt_cb (sub {
       my $str = $_[3];
       $str =~ s/\n(?=.)/\n+ /g;
       [$_[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
    });
 }
 =item C<nolog>
 Configures the context to not log anything by itself, which is the
 default. Same as C<< $ctx->log_cb (undef) >>.
+=item C<cap=>I<level>
+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<off>), meaning the priority will not be touched.
 =item C<0> or C<off>
-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<all>
 Enables all logging levels, i.e. filtering will effectively be switched
    my $pkg = sub {
       $_[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?
    };
    /\G[[:space:]]+/gc; # skip initial whitespace
       while (/\G((?:[^,:[:space:]]+|::|\\.)+)/gc) {
          for ("$1") {
             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);
             } elsif ($_ eq "all"             ) { $ctx->level ("all");
             } elsif ($_ eq "level"           ) { $ctx->level ("all"); $level = "level";
 This writes them only when the global logging level allows it, because
 it is attached to the default context which is invoked I<after> 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
 This writes them regardless of the global logging level, because it is
    PERL_ANYEVENT_LOG=%filelogger=file=/some/path:collect=+%filelogger
 In both cases, messages are still written to STDERR.
+=item Additionally log all messages with C<warn> and higher priority to
+C<syslog>, but cap at C<error>.
+This logs all messages to the default log target, but also logs messages
+with priority C<warn> or higher (and not filtered otherwise) to syslog
+facility C<user>. Messages with priority higher than C<error> will be
+logged with level C<error>.
+   $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<AnyEvent::Debug> to the default logging target(s).
 Attach the C<$AnyEvent::Log::LOG> context to the C<AnyEvent::Debug>
 context - this simply circumvents the global filtering for trace messages.

Diff Legend

-–
+Removed lines
-+
+Added lines
-<
+Changed lines
->
+Changed lines

Comparing AnyEvent/lib/AnyEvent/Log.pm (file contents): Revision 1.36 by root, Thu Aug 25 05:39:47 2011 UTC vs. Revision 1.45 by root, Sun Oct 2 00:42:04 2011 UTC

Diff Legend

Comparing AnyEvent/lib/AnyEvent/Log.pm (file contents):
Revision 1.36 by root, Thu Aug 25 05:39:47 2011 UTC vs.
Revision 1.45 by root, Sun Oct 2 00:42:04 2011 UTC