--- AnyEvent/lib/AnyEvent/Log.pm 2011/10/02 01:22:01 1.46 +++ AnyEvent/lib/AnyEvent/Log.pm 2019/03/11 20:48:19 1.66 @@ -8,15 +8,15 @@ use AnyEvent; - AE::log trace => "going to call function abc"; + 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 info => "file soandso successfully deleted"; - 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 + AE::log trace => "going to call function abc"; Log level overview: @@ -35,7 +35,7 @@ use AnyEvent::Log; - my $tracer = AnyEvent::Log::logger trace => \$my $trace; + my $tracer = AnyEvent::Log::logger trace => \my $trace; $tracer->("i am here") if $trace; $tracer->(sub { "lots of data: " . Dumper $self }) if $trace; @@ -63,18 +63,19 @@ 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"); 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. +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 module is also usable before AnyEvent itself is initialised, in which case some of the functionality might be reduced. @@ -108,24 +109,28 @@ 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 logged to STDERR by +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 single message at highest priority level -(C<1>, C), because logging a fatal message will also quit the -program - so use it sparingly :) +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 @@ -150,7 +155,7 @@ our ($now_int, $now_str1, $now_str2); # Format Time, not public - yet? -sub ft($) { +sub format_time($) { my $i = int $_[0]; my $f = sprintf "%06d", 1e6 * ($_[0] - $i); @@ -259,8 +264,8 @@ our @LEVEL2STR = qw(0 fatal alert crit error warn note info debug trace); # time, ctx, level, msg -sub _format($$$$) { - my $ts = ft $_[0]; +sub default_format($$$$) { + my $ts = format_time $_[0]; my $ct = " "; my @res; @@ -319,7 +324,7 @@ # format msg my $str = $ctx->[4] ? $ctx->[4]($now, $_[0], $level, $format) - : ($fmt[$level] ||= _format $now, $_[0], $level, $format); + : ($fmt[$level] ||= default_format $now, $_[0], $level, $format); $success = 1; @@ -451,6 +456,41 @@ C when logging a message before L becomes available. +=item AnyEvent::Log::format_time $timestamp + +Formats a timestamp as returned by C<< AnyEvent->now >> or C<< +AnyEvent->time >> or many other functions in the same way as +C does. + +In your main program (as opposed to in your module) you can override +the default timestamp display format by loading this module and then +redefining this function. + +Most commonly, this function can be used in formatting callbacks. + +=item AnyEvent::Log::default_format $time, $ctx, $level, $msg + +Format a log message using the given timestamp, logging context, log level +and log message. + +This is the formatting function used to format messages when no custom +function is provided. + +In your main program (as opposed to in your module) you can override the +default message format by loading this module and then redefining this +function. + +=item AnyEvent::Log::fatal_exit() + +This is the function that is called after logging a C log +message. It must not return. + +The default implementation simply calls C. + +In your main program (as opposed to in your module) you can override +the fatal exit function by loading this module and then redefining this +function. Make sure you don't return. + =back =head1 LOGGING CONTEXTS @@ -861,7 +901,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). @@ -896,15 +936,29 @@ 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. +To implement your own logging callback, you might find the +C and C +functions useful. + +Example: format the message just as AnyEvent::Log would, by letting +AnyEvent::Log do the work. This is a good basis to design a formatting +callback that only changes minor aspects of the formatting. + + $ctx->fmt_cb (sub { + my ($time, $ctx, $lvl, $msg) = @_; + + AnyEvent::Log::default_format $time, $ctx, $lvl, $msg + }); + Example: format just the raw message, with numeric log level in angle brackets. @@ -915,7 +969,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 { @@ -937,7 +991,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) @@ -982,28 +1037,100 @@ }); } +# 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 { @@ -1043,6 +1170,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 @@ -1099,6 +1230,9 @@ name is first mentioned. The difference to package contexts is that by default they have no attached slaves. +This makes it possible to create new log contexts that can be refered to +multiple times by name within the same log specification. + =item a perl package name Any other string references the logging context associated with the given @@ -1199,7 +1333,7 @@ =item C<+> -A line C<+> detaches all contexts, i.e. clears the slave list from the +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. @@ -1285,8 +1419,6 @@ } } -1; - =head1 EXAMPLES This section shows some common configurations, both as code, and as @@ -1369,10 +1501,18 @@ =back +=head1 ASYNCHRONOUS DISK I/O + +This module uses L to actually write log messages (in +C and C), so it doesn't block your program when +the disk is busy and a non-blocking L backend is available. + =head1 AUTHOR Marc Lehmann - http://home.schmorp.de/ + http://anyevent.schmorp.de =cut +1 +