1 |
=head1 NAME |
2 |
|
3 |
AnyEvent::Log - simple logging "framework" |
4 |
|
5 |
=head1 SYNOPSIS |
6 |
|
7 |
Simple uses: |
8 |
|
9 |
use AnyEvent; |
10 |
|
11 |
AE::log debug => "hit my knee"; |
12 |
AE::log warn => "it's a bit too hot"; |
13 |
AE::log error => "the flag was false!"; |
14 |
AE::log fatal => "the bit toggled! run!"; # never returns |
15 |
|
16 |
"Complex" uses (for speed sensitive code): |
17 |
|
18 |
use AnyEvent::Log; |
19 |
|
20 |
my $tracer = AnyEvent::Log::logger trace => \$my $trace; |
21 |
|
22 |
$tracer->("i am here") if $trace; |
23 |
$tracer->(sub { "lots of data: " . Dumper $self }) if $trace; |
24 |
|
25 |
Configuration (also look at the EXAMPLES section): |
26 |
|
27 |
# set logging for the current package to errors and higher only |
28 |
AnyEvent::Log::ctx->level ("error"); |
29 |
|
30 |
# set logging level to suppress anything below "notice" |
31 |
$AnyEvent::Log::FILTER->level ("notice"); |
32 |
|
33 |
# send all critical and higher priority messages to syslog, |
34 |
# regardless of (most) other settings |
35 |
$AnyEvent::Log::COLLECT->attach (new AnyEvent::Log::Ctx |
36 |
level => "critical", |
37 |
log_to_syslog => 0, |
38 |
); |
39 |
|
40 |
=head1 DESCRIPTION |
41 |
|
42 |
This module implements a relatively simple "logging framework". It doesn't |
43 |
attempt to be "the" logging solution or even "a" logging solution for |
44 |
AnyEvent - AnyEvent simply creates logging messages internally, and this |
45 |
module more or less exposes the mechanism, with some extra spiff to allow |
46 |
using it from other modules as well. |
47 |
|
48 |
Remember that the default verbosity level is C<0> (C<off>), so nothing |
49 |
will be logged, unless you set C<PERL_ANYEVENT_VERBOSE> to a higher number |
50 |
before starting your program, or change the logging level at runtime with |
51 |
something like: |
52 |
|
53 |
use AnyEvent::Log; |
54 |
AnyEvent::Log::FILTER->level ("info"); |
55 |
|
56 |
The design goal behind this module was to keep it simple (and small), |
57 |
but make it powerful enough to be potentially useful for any module, and |
58 |
extensive enough for the most common tasks, such as logging to multiple |
59 |
targets, or being able to log into a database. |
60 |
|
61 |
The amount of documentation might indicate otherwise, but the module is |
62 |
still just below 300 lines of code. |
63 |
|
64 |
=head1 LOGGING LEVELS |
65 |
|
66 |
Logging levels in this module range from C<1> (highest priority) to C<9> |
67 |
(lowest priority). Note that the lowest numerical value is the highest |
68 |
priority, so when this document says "higher priority" it means "lower |
69 |
numerical value". |
70 |
|
71 |
Instead of specifying levels by name you can also specify them by aliases: |
72 |
|
73 |
LVL NAME SYSLOG PERL NOTE |
74 |
1 fatal emerg exit aborts program! |
75 |
2 alert |
76 |
3 critical crit |
77 |
4 error err die |
78 |
5 warn warning |
79 |
6 note notice |
80 |
7 info |
81 |
8 debug |
82 |
9 trace |
83 |
|
84 |
As you can see, some logging levels have multiple aliases - the first one |
85 |
is the "official" name, the second one the "syslog" name (if it differs) |
86 |
and the third one the "perl" name, suggesting that you log C<die> messages |
87 |
at C<error> priority. |
88 |
|
89 |
You can normally only log a single message at highest priority level |
90 |
(C<1>, C<fatal>), because logging a fatal message will also quit the |
91 |
program - so use it sparingly :) |
92 |
|
93 |
Some methods also offer some extra levels, such as C<0>, C<off>, C<none> |
94 |
or C<all> - these are only valid in the methods they are documented for. |
95 |
|
96 |
=head1 LOGGING FUNCTIONS |
97 |
|
98 |
These functions allow you to log messages. They always use the caller's |
99 |
package as a "logging context". Also, the main logging function C<log> is |
100 |
callable as C<AnyEvent::log> or C<AE::log> when the C<AnyEvent> module is |
101 |
loaded. |
102 |
|
103 |
=over 4 |
104 |
|
105 |
=cut |
106 |
|
107 |
package AnyEvent::Log; |
108 |
|
109 |
use Carp (); |
110 |
use POSIX (); |
111 |
|
112 |
use AnyEvent (); BEGIN { AnyEvent::common_sense } |
113 |
use AnyEvent::Util (); |
114 |
|
115 |
our $VERSION = $AnyEvent::VERSION; |
116 |
|
117 |
our ($COLLECT, $FILTER, $LOG); |
118 |
|
119 |
our ($now_int, $now_str1, $now_str2); |
120 |
|
121 |
# Format Time, not public - yet? |
122 |
sub ft($) { |
123 |
my $i = int $_[0]; |
124 |
my $f = sprintf "%06d", 1e6 * ($_[0] - $i); |
125 |
|
126 |
($now_int, $now_str1, $now_str2) = ($i, split /\x01/, POSIX::strftime "%Y-%m-%d %H:%M:%S.\x01 %z", localtime $i) |
127 |
if $now_int != $i; |
128 |
|
129 |
"$now_str1$f$now_str2" |
130 |
} |
131 |
|
132 |
our %CTX; # all package contexts |
133 |
|
134 |
# creates a default package context object for the given package |
135 |
sub _pkg_ctx($) { |
136 |
my $ctx = bless [$_[0], (1 << 10) - 1 - 1, {}], "AnyEvent::Log::Ctx"; |
137 |
|
138 |
# link "parent" package |
139 |
my $parent = $_[0] =~ /^(.+)::/ |
140 |
? $CTX{$1} ||= &_pkg_ctx ("$1") |
141 |
: $COLLECT; |
142 |
|
143 |
$ctx->[2]{$parent+0} = $parent; |
144 |
|
145 |
$ctx |
146 |
} |
147 |
|
148 |
=item AnyEvent::Log::log $level, $msg[, @args] |
149 |
|
150 |
Requests logging of the given C<$msg> with the given log level, and |
151 |
returns true if the message was logged I<somewhere>. |
152 |
|
153 |
For C<fatal> log levels, the program will abort. |
154 |
|
155 |
If only a C<$msg> is given, it is logged as-is. With extra C<@args>, the |
156 |
C<$msg> is interpreted as an sprintf format string. |
157 |
|
158 |
The C<$msg> should not end with C<\n>, but may if that is convenient for |
159 |
you. Also, multiline messages are handled properly. |
160 |
|
161 |
Last not least, C<$msg> might be a code reference, in which case it is |
162 |
supposed to return the message. It will be called only then the message |
163 |
actually gets logged, which is useful if it is costly to create the |
164 |
message in the first place. |
165 |
|
166 |
Whether the given message will be logged depends on the maximum log level |
167 |
and the caller's package. The return value can be used to ensure that |
168 |
messages or not "lost" - for example, when L<AnyEvent::Debug> detects a |
169 |
runtime error it tries to log it at C<die> level, but if that message is |
170 |
lost it simply uses warn. |
171 |
|
172 |
Note that you can (and should) call this function as C<AnyEvent::log> or |
173 |
C<AE::log>, without C<use>-ing this module if possible (i.e. you don't |
174 |
need any additional functionality), as those functions will load the |
175 |
logging module on demand only. They are also much shorter to write. |
176 |
|
177 |
Also, if you optionally generate a lot of debug messages (such as when |
178 |
tracing some code), you should look into using a logger callback and a |
179 |
boolean enabler (see C<logger>, below). |
180 |
|
181 |
Example: log something at error level. |
182 |
|
183 |
AE::log error => "something"; |
184 |
|
185 |
Example: use printf-formatting. |
186 |
|
187 |
AE::log info => "%5d %-10.10s %s", $index, $category, $msg; |
188 |
|
189 |
Example: only generate a costly dump when the message is actually being logged. |
190 |
|
191 |
AE::log debug => sub { require Data::Dump; Data::Dump::dump \%cache }; |
192 |
|
193 |
=cut |
194 |
|
195 |
# also allow syslog equivalent names |
196 |
our %STR2LEVEL = ( |
197 |
fatal => 1, emerg => 1, exit => 1, |
198 |
alert => 2, |
199 |
critical => 3, crit => 3, |
200 |
error => 4, err => 4, die => 4, |
201 |
warn => 5, warning => 5, |
202 |
note => 6, notice => 6, |
203 |
info => 7, |
204 |
debug => 8, |
205 |
trace => 9, |
206 |
); |
207 |
|
208 |
sub now () { time } |
209 |
|
210 |
AnyEvent::post_detect { |
211 |
*now = \&AE::now; |
212 |
}; |
213 |
|
214 |
our @LEVEL2STR = qw(0 fatal alert crit error warn note info debug trace); |
215 |
|
216 |
# time, ctx, level, msg |
217 |
sub _format($$$$) { |
218 |
my $ts = ft $_[0]; |
219 |
my $ct = " "; |
220 |
|
221 |
my @res; |
222 |
|
223 |
for (split /\n/, sprintf "%-5s %s: %s", $LEVEL2STR[$_[2]], $_[1][0], $_[3]) { |
224 |
push @res, "$ts$ct$_\n"; |
225 |
$ct = " + "; |
226 |
} |
227 |
|
228 |
join "", @res |
229 |
} |
230 |
|
231 |
sub _log { |
232 |
my ($ctx, $level, $format, @args) = @_; |
233 |
|
234 |
$level = $level > 0 && $level <= 9 |
235 |
? $level+0 |
236 |
: $STR2LEVEL{$level} || Carp::croak "$level: not a valid logging level, caught"; |
237 |
|
238 |
my $mask = 1 << $level; |
239 |
|
240 |
my ($success, %seen, @ctx, $now, $fmt); |
241 |
|
242 |
do |
243 |
{ |
244 |
# skip if masked |
245 |
if ($ctx->[1] & $mask && !$seen{$ctx+0}++) { |
246 |
if ($ctx->[3]) { |
247 |
# logging target found |
248 |
|
249 |
# now get raw message, unless we have it already |
250 |
unless ($now) { |
251 |
$format = $format->() if ref $format; |
252 |
$format = sprintf $format, @args if @args; |
253 |
$format =~ s/\n$//; |
254 |
$now = AE::now; |
255 |
}; |
256 |
|
257 |
# format msg |
258 |
my $str = $ctx->[4] |
259 |
? $ctx->[4]($now, $_[0], $level, $format) |
260 |
: ($fmt ||= _format $now, $_[0], $level, $format); |
261 |
|
262 |
$success = 1; |
263 |
|
264 |
$ctx->[3]($str) |
265 |
or push @ctx, values %{ $ctx->[2] }; # not consumed - propagate |
266 |
} else { |
267 |
push @ctx, values %{ $ctx->[2] }; # not masked - propagate |
268 |
} |
269 |
} |
270 |
} |
271 |
while $ctx = pop @ctx; |
272 |
|
273 |
exit 1 if $level <= 1; |
274 |
|
275 |
$success |
276 |
} |
277 |
|
278 |
sub log($$;@) { |
279 |
_log |
280 |
$CTX{ (caller)[0] } ||= _pkg_ctx +(caller)[0], |
281 |
@_; |
282 |
} |
283 |
|
284 |
*AnyEvent::log = *AE::log = \&log; |
285 |
|
286 |
=item $logger = AnyEvent::Log::logger $level[, \$enabled] |
287 |
|
288 |
Creates a code reference that, when called, acts as if the |
289 |
C<AnyEvent::Log::log> function was called at this point with the given |
290 |
level. C<$logger> is passed a C<$msg> and optional C<@args>, just as with |
291 |
the C<AnyEvent::Log::log> function: |
292 |
|
293 |
my $debug_log = AnyEvent::Log::logger "debug"; |
294 |
|
295 |
$debug_log->("debug here"); |
296 |
$debug_log->("%06d emails processed", 12345); |
297 |
$debug_log->(sub { $obj->as_string }); |
298 |
|
299 |
The idea behind this function is to decide whether to log before actually |
300 |
logging - when the C<logger> function is called once, but the returned |
301 |
logger callback often, then this can be a tremendous speed win. |
302 |
|
303 |
Despite this speed advantage, changes in logging configuration will |
304 |
still be reflected by the logger callback, even if configuration changes |
305 |
I<after> it was created. |
306 |
|
307 |
To further speed up logging, you can bind a scalar variable to the logger, |
308 |
which contains true if the logger should be called or not - if it is |
309 |
false, calling the logger can be safely skipped. This variable will be |
310 |
updated as long as C<$logger> is alive. |
311 |
|
312 |
Full example: |
313 |
|
314 |
# near the init section |
315 |
use AnyEvent::Log; |
316 |
|
317 |
my $debug_log = AnyEvent:Log::logger debug => \my $debug; |
318 |
|
319 |
# and later in your program |
320 |
$debug_log->("yo, stuff here") if $debug; |
321 |
|
322 |
$debug and $debug_log->("123"); |
323 |
|
324 |
=cut |
325 |
|
326 |
our %LOGGER; |
327 |
|
328 |
# re-assess logging status for all loggers |
329 |
sub _reassess { |
330 |
local $SIG{__DIE__}; |
331 |
my $die = sub { die }; |
332 |
|
333 |
for (@_ ? $LOGGER{$_[0]} : values %LOGGER) { |
334 |
my ($ctx, $level, $renabled) = @$_; |
335 |
|
336 |
# to detect whether a message would be logged, we actually |
337 |
# try to log one and die. this isn't fast, but we can be |
338 |
# sure that the logging decision is correct :) |
339 |
|
340 |
$$renabled = !eval { |
341 |
_log $ctx, $level, $die; |
342 |
|
343 |
1 |
344 |
}; |
345 |
} |
346 |
} |
347 |
|
348 |
sub _logger { |
349 |
my ($ctx, $level, $renabled) = @_; |
350 |
|
351 |
$$renabled = 1; |
352 |
|
353 |
my $logger = [$ctx, $level, $renabled]; |
354 |
|
355 |
$LOGGER{$logger+0} = $logger; |
356 |
|
357 |
_reassess $logger+0; |
358 |
|
359 |
my $guard = AnyEvent::Util::guard { |
360 |
# "clean up" |
361 |
delete $LOGGER{$logger+0}; |
362 |
}; |
363 |
|
364 |
sub { |
365 |
$guard if 0; # keep guard alive, but don't cause runtime overhead |
366 |
|
367 |
_log $ctx, $level, @_ |
368 |
if $$renabled; |
369 |
} |
370 |
} |
371 |
|
372 |
sub logger($;$) { |
373 |
_logger |
374 |
$CTX{ (caller)[0] } ||= _pkg_ctx +(caller)[0], |
375 |
@_ |
376 |
} |
377 |
|
378 |
=back |
379 |
|
380 |
=head1 LOGGING CONTEXTS |
381 |
|
382 |
This module associates every log message with a so-called I<logging |
383 |
context>, based on the package of the caller. Every perl package has its |
384 |
own logging context. |
385 |
|
386 |
A logging context has three major responsibilities: filtering, logging and |
387 |
propagating the message. |
388 |
|
389 |
For the first purpose, filtering, each context has a set of logging |
390 |
levels, called the log level mask. Messages not in the set will be ignored |
391 |
by this context (masked). |
392 |
|
393 |
For logging, the context stores a formatting callback (which takes the |
394 |
timestamp, context, level and string message and formats it in the way |
395 |
it should be logged) and a logging callback (which is responsible for |
396 |
actually logging the formatted message and telling C<AnyEvent::Log> |
397 |
whether it has consumed the message, or whether it should be propagated). |
398 |
|
399 |
For propagation, a context can have any number of attached I<slave |
400 |
contexts>. Any message that is neither masked by the logging mask nor |
401 |
masked by the logging callback returning true will be passed to all slave |
402 |
contexts. |
403 |
|
404 |
Each call to a logging function will log the message at most once per |
405 |
context, so it does not matter (much) if there are cycles or if the |
406 |
message can arrive at the same context via multiple paths. |
407 |
|
408 |
=head2 DEFAULTS |
409 |
|
410 |
By default, all logging contexts have an full set of log levels ("all"), a |
411 |
disabled logging callback and the default formatting callback. |
412 |
|
413 |
Package contexts have the package name as logging title by default. |
414 |
|
415 |
They have exactly one slave - the context of the "parent" package. The |
416 |
parent package is simply defined to be the package name without the last |
417 |
component, i.e. C<AnyEvent::Debug::Wrapped> becomes C<AnyEvent::Debug>, |
418 |
and C<AnyEvent> becomes ... C<$AnyEvent::Log::COLLECT> which is the |
419 |
exception of the rule - just like the "parent" of any single-component |
420 |
package name in Perl is C<main>, the default slave of any top-level |
421 |
package context is C<$AnyEvent::Log::COLLECT>. |
422 |
|
423 |
Since perl packages form only an approximate hierarchy, this slave |
424 |
context can of course be removed. |
425 |
|
426 |
All other (anonymous) contexts have no slaves and an empty title by |
427 |
default. |
428 |
|
429 |
When the module is loaded it creates the C<$AnyEvent::Log::LOG> logging |
430 |
context that simply logs everything via C<warn>, without propagating |
431 |
anything anywhere by default. The purpose of this context is to provide |
432 |
a convenient place to override the global logging target or to attach |
433 |
additional log targets. It's not meant for filtering. |
434 |
|
435 |
It then creates the C<$AnyEvent::Log::FILTER> context whose |
436 |
purpose is to suppress all messages with priority higher |
437 |
than C<$ENV{PERL_ANYEVENT_VERBOSE}>. It then attached the |
438 |
C<$AnyEvent::Log::LOG> context to it. The purpose of the filter context |
439 |
is to simply provide filtering according to some global log level. |
440 |
|
441 |
Finally it creates the top-level package context C<$AnyEvent::Log::COLLECT> |
442 |
and attaches the C<$AnyEvent::Log::FILTER> context to it, but otherwise |
443 |
leaves it at default config. Its purpose is simply to collect all log |
444 |
messages system-wide. |
445 |
|
446 |
The hierarchy is then: |
447 |
|
448 |
any package, eventually -> $COLLECT -> $FILTER -> $LOG |
449 |
|
450 |
The effect of all this is that log messages, by default, wander up to the |
451 |
C<$AnyEvent::Log::COLLECT> context where all messages normally end up, |
452 |
from there to C<$AnyEvent::Log::FILTER> where log messages with lower |
453 |
priority then C<$ENV{PERL_ANYEVENT_VERBOSE}> will be filtered out and then |
454 |
to the C<$AnyEvent::Log::LOG> context to be passed to C<warn>. |
455 |
|
456 |
This makes it easy to set a global logging level (by modifying $FILTER), |
457 |
but still allow other contexts to send, for example, their debug and trace |
458 |
messages to the $LOG target despite the global logging level, or to attach |
459 |
additional log targets that log messages, regardless of the global logging |
460 |
level. |
461 |
|
462 |
It also makes it easy to modify the default warn-logger ($LOG) to |
463 |
something that logs to a file, or to attach additional logging targets |
464 |
(such as loggign to a file) by attaching it to $FILTER. |
465 |
|
466 |
=head2 CREATING/FINDING/DESTROYING CONTEXTS |
467 |
|
468 |
=over 4 |
469 |
|
470 |
=item $ctx = AnyEvent::Log::ctx [$pkg] |
471 |
|
472 |
This function creates or returns a logging context (which is an object). |
473 |
|
474 |
If a package name is given, then the context for that packlage is |
475 |
returned. If it is called without any arguments, then the context for the |
476 |
callers package is returned (i.e. the same context as a C<AE::log> call |
477 |
would use). |
478 |
|
479 |
If C<undef> is given, then it creates a new anonymous context that is not |
480 |
tied to any package and is destroyed when no longer referenced. |
481 |
|
482 |
=cut |
483 |
|
484 |
sub ctx(;$) { |
485 |
my $pkg = @_ ? shift : (caller)[0]; |
486 |
|
487 |
ref $pkg |
488 |
? $pkg |
489 |
: defined $pkg |
490 |
? $CTX{$pkg} ||= AnyEvent::Log::_pkg_ctx $pkg |
491 |
: bless [undef, (1 << 10) - 1 - 1], "AnyEvent::Log::Ctx" |
492 |
} |
493 |
|
494 |
=item AnyEvent::Log::reset |
495 |
|
496 |
Resets all package contexts and recreates the default hierarchy if |
497 |
necessary, i.e. resets the logging subsystem to defaults, as much as |
498 |
possible. This process keeps references to contexts held by other parts of |
499 |
the program intact. |
500 |
|
501 |
This can be used to implement config-file (re-)loading: before loading a |
502 |
configuration, reset all contexts. |
503 |
|
504 |
=cut |
505 |
|
506 |
sub reset { |
507 |
# hard to kill complex data structures |
508 |
# we "recreate" all package loggers and reset the hierarchy |
509 |
while (my ($k, $v) = each %CTX) { |
510 |
@$v = ($k, (1 << 10) - 1 - 1, { }); |
511 |
|
512 |
$v->attach ($k =~ /^(.+)::/ ? $CTX{$1} : $AnyEvent::Log::COLLECT); |
513 |
} |
514 |
|
515 |
@$_ = ($_->[0], (1 << 10) - 1 - 1) |
516 |
for $LOG, $FILTER, $COLLECT; |
517 |
|
518 |
$LOG->slaves; |
519 |
$LOG->title ('$AnyEvent::Log::LOG'); |
520 |
$LOG->log_to_warn; |
521 |
|
522 |
$FILTER->slaves ($LOG); |
523 |
$FILTER->title ('$AnyEvent::Log::FILTER'); |
524 |
$FILTER->level ($AnyEvent::VERBOSE); |
525 |
|
526 |
$COLLECT->slaves ($FILTER); |
527 |
$COLLECT->title ('$AnyEvent::Log::COLLECT'); |
528 |
|
529 |
_reassess; |
530 |
} |
531 |
|
532 |
# create the default logger contexts |
533 |
$LOG = ctx undef; |
534 |
$FILTER = ctx undef; |
535 |
$COLLECT = ctx undef; |
536 |
|
537 |
AnyEvent::Log::reset; |
538 |
|
539 |
# hello, CPAN, please catch me |
540 |
package AnyEvent::Log::LOG; |
541 |
package AE::Log::LOG; |
542 |
package AnyEvent::Log::FILTER; |
543 |
package AE::Log::FILTER; |
544 |
package AnyEvent::Log::COLLECT; |
545 |
package AE::Log::COLLECT; |
546 |
|
547 |
package AnyEvent::Log::Ctx; |
548 |
|
549 |
# 0 1 2 3 4 |
550 |
# [$title, $level, %$slaves, &$logcb, &$fmtcb] |
551 |
|
552 |
=item $ctx = new AnyEvent::Log::Ctx methodname => param... |
553 |
|
554 |
This is a convenience constructor that makes it simpler to construct |
555 |
anonymous logging contexts. |
556 |
|
557 |
Each key-value pair results in an invocation of the method of the same |
558 |
name as the key with the value as parameter, unless the value is an |
559 |
arrayref, in which case it calls the method with the contents of the |
560 |
array. The methods are called in the same order as specified. |
561 |
|
562 |
Example: create a new logging context and set both the default logging |
563 |
level, some slave contexts and a logging callback. |
564 |
|
565 |
$ctx = new AnyEvent::Log::Ctx |
566 |
title => "dubious messages", |
567 |
level => "error", |
568 |
log_cb => sub { print STDOUT shift; 0 }, |
569 |
slaves => [$ctx1, $ctx, $ctx2], |
570 |
; |
571 |
|
572 |
=back |
573 |
|
574 |
=cut |
575 |
|
576 |
sub new { |
577 |
my $class = shift; |
578 |
|
579 |
my $ctx = AnyEvent::Log::ctx undef; |
580 |
|
581 |
while (@_) { |
582 |
my ($k, $v) = splice @_, 0, 2; |
583 |
$ctx->$k (ref $v eq "ARRAY" ? @$v : $v); |
584 |
} |
585 |
|
586 |
bless $ctx, $class # do we really support subclassing, hmm? |
587 |
} |
588 |
|
589 |
|
590 |
=head2 CONFIGURING A LOG CONTEXT |
591 |
|
592 |
The following methods can be used to configure the logging context. |
593 |
|
594 |
=over 4 |
595 |
|
596 |
=item $ctx->title ([$new_title]) |
597 |
|
598 |
Returns the title of the logging context - this is the package name, for |
599 |
package contexts, and a user defined string for all others. |
600 |
|
601 |
If C<$new_title> is given, then it replaces the package name or title. |
602 |
|
603 |
=cut |
604 |
|
605 |
sub title { |
606 |
$_[0][0] = $_[1] if @_ > 1; |
607 |
$_[0][0] |
608 |
} |
609 |
|
610 |
=back |
611 |
|
612 |
=head3 LOGGING LEVELS |
613 |
|
614 |
The following methods deal with the logging level set associated with the |
615 |
log context. |
616 |
|
617 |
The most common method to use is probably C<< $ctx->level ($level) >>, |
618 |
which configures the specified and any higher priority levels. |
619 |
|
620 |
All functions which accept a list of levels also accept the special string |
621 |
C<all> which expands to all logging levels. |
622 |
|
623 |
=over 4 |
624 |
|
625 |
=item $ctx->levels ($level[, $level...) |
626 |
|
627 |
Enables logging for the given levels and disables it for all others. |
628 |
|
629 |
=item $ctx->level ($level) |
630 |
|
631 |
Enables logging for the given level and all lower level (higher priority) |
632 |
ones. In addition to normal logging levels, specifying a level of C<0> or |
633 |
C<off> disables all logging for this level. |
634 |
|
635 |
Example: log warnings, errors and higher priority messages. |
636 |
|
637 |
$ctx->level ("warn"); |
638 |
$ctx->level (5); # same thing, just numeric |
639 |
|
640 |
=item $ctx->enable ($level[, $level...]) |
641 |
|
642 |
Enables logging for the given levels, leaving all others unchanged. |
643 |
|
644 |
=item $ctx->disable ($level[, $level...]) |
645 |
|
646 |
Disables logging for the given levels, leaving all others unchanged. |
647 |
|
648 |
=cut |
649 |
|
650 |
sub _lvl_lst { |
651 |
map { |
652 |
$_ > 0 && $_ <= 9 ? $_+0 |
653 |
: $_ eq "all" ? (1 .. 9) |
654 |
: $STR2LEVEL{$_} || Carp::croak "$_: not a valid logging level, caught" |
655 |
} @_ |
656 |
} |
657 |
|
658 |
our $NOP_CB = sub { 0 }; |
659 |
|
660 |
sub levels { |
661 |
my $ctx = shift; |
662 |
$ctx->[1] = 0; |
663 |
$ctx->[1] |= 1 << $_ |
664 |
for &_lvl_lst; |
665 |
AnyEvent::Log::_reassess; |
666 |
} |
667 |
|
668 |
sub level { |
669 |
my $ctx = shift; |
670 |
my $lvl = $_[0] =~ /^(?:0|off|none)$/ ? 0 : (_lvl_lst $_[0])[-1]; |
671 |
|
672 |
$ctx->[1] = ((1 << $lvl) - 1) << 1; |
673 |
AnyEvent::Log::_reassess; |
674 |
} |
675 |
|
676 |
sub enable { |
677 |
my $ctx = shift; |
678 |
$ctx->[1] |= 1 << $_ |
679 |
for &_lvl_lst; |
680 |
AnyEvent::Log::_reassess; |
681 |
} |
682 |
|
683 |
sub disable { |
684 |
my $ctx = shift; |
685 |
$ctx->[1] &= ~(1 << $_) |
686 |
for &_lvl_lst; |
687 |
AnyEvent::Log::_reassess; |
688 |
} |
689 |
|
690 |
=back |
691 |
|
692 |
=head3 SLAVE CONTEXTS |
693 |
|
694 |
The following methods attach and detach another logging context to a |
695 |
logging context. |
696 |
|
697 |
Log messages are propagated to all slave contexts, unless the logging |
698 |
callback consumes the message. |
699 |
|
700 |
=over 4 |
701 |
|
702 |
=item $ctx->attach ($ctx2[, $ctx3...]) |
703 |
|
704 |
Attaches the given contexts as slaves to this context. It is not an error |
705 |
to add a context twice (the second add will be ignored). |
706 |
|
707 |
A context can be specified either as package name or as a context object. |
708 |
|
709 |
=item $ctx->detach ($ctx2[, $ctx3...]) |
710 |
|
711 |
Removes the given slaves from this context - it's not an error to attempt |
712 |
to remove a context that hasn't been added. |
713 |
|
714 |
A context can be specified either as package name or as a context object. |
715 |
|
716 |
=item $ctx->slaves ($ctx2[, $ctx3...]) |
717 |
|
718 |
Replaces all slaves attached to this context by the ones given. |
719 |
|
720 |
=cut |
721 |
|
722 |
sub attach { |
723 |
my $ctx = shift; |
724 |
|
725 |
$ctx->[2]{$_+0} = $_ |
726 |
for map { AnyEvent::Log::ctx $_ } @_; |
727 |
} |
728 |
|
729 |
sub detach { |
730 |
my $ctx = shift; |
731 |
|
732 |
delete $ctx->[2]{$_+0} |
733 |
for map { AnyEvent::Log::ctx $_ } @_; |
734 |
} |
735 |
|
736 |
sub slaves { |
737 |
undef $_[0][2]; |
738 |
&attach; |
739 |
} |
740 |
|
741 |
=back |
742 |
|
743 |
=head3 LOG TARGETS |
744 |
|
745 |
The following methods configure how the logging context actually does |
746 |
the logging (which consists of formatting the message and printing it or |
747 |
whatever it wants to do with it). |
748 |
|
749 |
=over 4 |
750 |
|
751 |
=item $ctx->log_cb ($cb->($str) |
752 |
|
753 |
Replaces the logging callback on the context (C<undef> disables the |
754 |
logging callback). |
755 |
|
756 |
The logging callback is responsible for handling formatted log messages |
757 |
(see C<fmt_cb> below) - normally simple text strings that end with a |
758 |
newline (and are possibly multiline themselves). |
759 |
|
760 |
It also has to return true iff it has consumed the log message, and false |
761 |
if it hasn't. Consuming a message means that it will not be sent to any |
762 |
slave context. When in doubt, return C<0> from your logging callback. |
763 |
|
764 |
Example: a very simple logging callback, simply dump the message to STDOUT |
765 |
and do not consume it. |
766 |
|
767 |
$ctx->log_cb (sub { print STDERR shift; 0 }); |
768 |
|
769 |
You can filter messages by having a log callback that simply returns C<1> |
770 |
and does not do anything with the message, but this counts as "message |
771 |
being logged" and might not be very efficient. |
772 |
|
773 |
Example: propagate all messages except for log levels "debug" and |
774 |
"trace". The messages will still be generated, though, which can slow down |
775 |
your program. |
776 |
|
777 |
$ctx->levels ("debug", "trace"); |
778 |
$ctx->log_cb (sub { 1 }); # do not log, but eat debug and trace messages |
779 |
|
780 |
=item $ctx->fmt_cb ($fmt_cb->($timestamp, $orig_ctx, $level, $message)) |
781 |
|
782 |
Replaces the formatting callback on the context (C<undef> restores the |
783 |
default formatter). |
784 |
|
785 |
The callback is passed the (possibly fractional) timestamp, the original |
786 |
logging context, the (numeric) logging level and the raw message string |
787 |
and needs to return a formatted log message. In most cases this will be a |
788 |
string, but it could just as well be an array reference that just stores |
789 |
the values. |
790 |
|
791 |
If, for some reason, you want to use C<caller> to find out more baout the |
792 |
logger then you should walk up the call stack until you are no longer |
793 |
inside the C<AnyEvent::Log> package. |
794 |
|
795 |
Example: format just the raw message, with numeric log level in angle |
796 |
brackets. |
797 |
|
798 |
$ctx->fmt_cb (sub { |
799 |
my ($time, $ctx, $lvl, $msg) = @_; |
800 |
|
801 |
"<$lvl>$msg\n" |
802 |
}); |
803 |
|
804 |
Example: return an array reference with just the log values, and use |
805 |
C<PApp::SQL::sql_exec> to store the emssage in a database. |
806 |
|
807 |
$ctx->fmt_cb (sub { \@_ }); |
808 |
$ctx->log_cb (sub { |
809 |
my ($msg) = @_; |
810 |
|
811 |
sql_exec "insert into log (when, subsys, prio, msg) values (?, ?, ?, ?)", |
812 |
$msg->[0] + 0, |
813 |
"$msg->[1]", |
814 |
$msg->[2] + 0, |
815 |
"$msg->[3]"; |
816 |
|
817 |
0 |
818 |
}); |
819 |
|
820 |
=item $ctx->log_to_warn |
821 |
|
822 |
Sets the C<log_cb> to simply use C<CORE::warn> to report any messages |
823 |
(usually this logs to STDERR). |
824 |
|
825 |
=item $ctx->log_to_file ($path) |
826 |
|
827 |
Sets the C<log_cb> to log to a file (by appending), unbuffered. |
828 |
|
829 |
=item $ctx->log_to_path ($path) |
830 |
|
831 |
Same as C<< ->log_to_file >>, but opens the file for each message. This |
832 |
is much slower, but allows you to change/move/rename/delete the file at |
833 |
basically any time. |
834 |
|
835 |
Needless(?) to say, if you do not want to be bitten by some evil person |
836 |
calling C<chdir>, the path should be absolute. Doesn't help with |
837 |
C<chroot>, but hey... |
838 |
|
839 |
=item $ctx->log_to_syslog ([$log_flags]) |
840 |
|
841 |
Logs all messages via L<Sys::Syslog>, mapping C<trace> to C<debug> and all |
842 |
the others in the obvious way. If specified, then the C<$log_flags> are |
843 |
simply or'ed onto the priority argument and can contain any C<LOG_xxx> |
844 |
flags valid for Sys::Syslog::syslog, except for the priority levels. |
845 |
|
846 |
Note that this function also sets a C<fmt_cb> - the logging part requires |
847 |
an array reference with [$level, $str] as input. |
848 |
|
849 |
=cut |
850 |
|
851 |
sub log_cb { |
852 |
my ($ctx, $cb) = @_; |
853 |
|
854 |
$ctx->[3] = $cb; |
855 |
} |
856 |
|
857 |
sub fmt_cb { |
858 |
my ($ctx, $cb) = @_; |
859 |
|
860 |
$ctx->[4] = $cb; |
861 |
} |
862 |
|
863 |
sub log_to_warn { |
864 |
my ($ctx, $path) = @_; |
865 |
|
866 |
$ctx->log_cb (sub { |
867 |
warn shift; |
868 |
0 |
869 |
}); |
870 |
} |
871 |
|
872 |
sub log_to_file { |
873 |
my ($ctx, $path) = @_; |
874 |
|
875 |
open my $fh, ">>", $path |
876 |
or die "$path: $!"; |
877 |
|
878 |
$ctx->log_cb (sub { |
879 |
syswrite $fh, shift; |
880 |
0 |
881 |
}); |
882 |
} |
883 |
|
884 |
sub log_to_path { |
885 |
my ($ctx, $path) = @_; |
886 |
|
887 |
$ctx->log_cb (sub { |
888 |
open my $fh, ">>", $path |
889 |
or die "$path: $!"; |
890 |
|
891 |
syswrite $fh, shift; |
892 |
0 |
893 |
}); |
894 |
} |
895 |
|
896 |
sub log_to_syslog { |
897 |
my ($ctx, $flags) = @_; |
898 |
|
899 |
require Sys::Syslog; |
900 |
|
901 |
$ctx->fmt_cb (sub { |
902 |
my $str = $_[3]; |
903 |
$str =~ s/\n(?=.)/\n+ /g; |
904 |
|
905 |
[$_[2], "($_[1][0]) $str"] |
906 |
}); |
907 |
|
908 |
$ctx->log_cb (sub { |
909 |
my $lvl = $_[0][0] < 9 ? $_[0][0] : 8; |
910 |
|
911 |
Sys::Syslog::syslog ($flags | ($lvl - 1), $_) |
912 |
for split /\n/, $_[0][1]; |
913 |
|
914 |
0 |
915 |
}); |
916 |
} |
917 |
|
918 |
=back |
919 |
|
920 |
=head3 MESSAGE LOGGING |
921 |
|
922 |
These methods allow you to log messages directly to a context, without |
923 |
going via your package context. |
924 |
|
925 |
=over 4 |
926 |
|
927 |
=item $ctx->log ($level, $msg[, @params]) |
928 |
|
929 |
Same as C<AnyEvent::Log::log>, but uses the given context as log context. |
930 |
|
931 |
=item $logger = $ctx->logger ($level[, \$enabled]) |
932 |
|
933 |
Same as C<AnyEvent::Log::logger>, but uses the given context as log |
934 |
context. |
935 |
|
936 |
=cut |
937 |
|
938 |
*log = \&AnyEvent::Log::_log; |
939 |
*logger = \&AnyEvent::Log::_logger; |
940 |
|
941 |
=back |
942 |
|
943 |
=cut |
944 |
|
945 |
package AnyEvent::Log; |
946 |
|
947 |
=head1 CONFIGURATION VIA $ENV{PERL_ANYEVENT_LOG} |
948 |
|
949 |
Logging can also be configured by setting the environment variable |
950 |
C<PERL_ANYEVENT_LOG> (or C<AE_LOG>). |
951 |
|
952 |
The value consists of one or more logging context specifications separated |
953 |
by C<:> or whitespace. Each logging specification in turn starts with a |
954 |
context name, followed by C<=>, followed by zero or more comma-separated |
955 |
configuration directives, here are some examples: |
956 |
|
957 |
# set default logging level |
958 |
filter=warn |
959 |
|
960 |
# log to file instead of to stderr |
961 |
log=file=/tmp/mylog |
962 |
|
963 |
# log to file in addition to stderr |
964 |
log=+%file:%file=file=/tmp/mylog |
965 |
|
966 |
# enable debug log messages, log warnings and above to syslog |
967 |
filter=debug:log=+%warnings:%warnings=warn,syslog=LOG_LOCAL0 |
968 |
|
969 |
# log trace messages (only) from AnyEvent::Debug to file |
970 |
AnyEvent::Debug=+%trace:%trace=only,trace,file=/tmp/tracelog |
971 |
|
972 |
A context name in the log specification can be any of the following: |
973 |
|
974 |
=over 4 |
975 |
|
976 |
=item C<collect>, C<filter>, C<log> |
977 |
|
978 |
Correspond to the three predefined C<$AnyEvent::Log::COLLECT>, |
979 |
C<AnyEvent::Log::FILTER> and C<$AnyEvent::Log::LOG> contexts. |
980 |
|
981 |
=item C<%name> |
982 |
|
983 |
Context names starting with a C<%> are anonymous contexts created when the |
984 |
name is first mentioned. The difference to package contexts is that by |
985 |
default they have no attached slaves. |
986 |
|
987 |
=item a perl package name |
988 |
|
989 |
Any other string references the logging context associated with the given |
990 |
Perl C<package>. In the unlikely case where you want to specify a package |
991 |
context that matches on of the other context name forms, you can add a |
992 |
C<::> to the package name to force interpretation as a package. |
993 |
|
994 |
=back |
995 |
|
996 |
The configuration specifications can be any number of the following: |
997 |
|
998 |
=over 4 |
999 |
|
1000 |
=item C<stderr> |
1001 |
|
1002 |
Configures the context to use Perl's C<warn> function (which typically |
1003 |
logs to C<STDERR>). Works like C<log_to_warn>. |
1004 |
|
1005 |
=item C<file=>I<path> |
1006 |
|
1007 |
Configures the context to log to a file with the given path. Works like |
1008 |
C<log_to_file>. |
1009 |
|
1010 |
=item C<path=>I<path> |
1011 |
|
1012 |
Configures the context to log to a file with the given path. Works like |
1013 |
C<log_to_path>. |
1014 |
|
1015 |
=item C<syslog> or C<syslog=>I<expr> |
1016 |
|
1017 |
Configured the context to log to syslog. If I<expr> is given, then it is |
1018 |
evaluated in the L<Sys::Syslog> package, so you could use: |
1019 |
|
1020 |
log=syslog=LOG_LOCAL0 |
1021 |
|
1022 |
=item C<nolog> |
1023 |
|
1024 |
Configures the context to not log anything by itself, which is the |
1025 |
default. Same as C<< $ctx->log_cb (undef) >>. |
1026 |
|
1027 |
=item C<0> or C<off> |
1028 |
|
1029 |
Sets the logging level of the context ot C<0>, i.e. all messages will be |
1030 |
filtered out. |
1031 |
|
1032 |
=item C<all> |
1033 |
|
1034 |
Enables all logging levels, i.e. filtering will effectively be switched |
1035 |
off (the default). |
1036 |
|
1037 |
=item C<only> |
1038 |
|
1039 |
Disables all logging levels, and changes the interpretation of following |
1040 |
level specifications to enable the specified level only. |
1041 |
|
1042 |
Example: only enable debug messages for a context. |
1043 |
|
1044 |
context=only,debug |
1045 |
|
1046 |
=item C<except> |
1047 |
|
1048 |
Enables all logging levels, and changes the interpretation of following |
1049 |
level specifications to disable that level. Rarely used. |
1050 |
|
1051 |
Example: enable all logging levels except fatal and trace (this is rather |
1052 |
nonsensical). |
1053 |
|
1054 |
filter=exept,fatal,trace |
1055 |
|
1056 |
=item C<level> |
1057 |
|
1058 |
Enables all logging levels, and changes the interpretation of following |
1059 |
level specifications to be "that level or any higher priority |
1060 |
message". This is the default. |
1061 |
|
1062 |
Example: log anything at or above warn level. |
1063 |
|
1064 |
filter=warn |
1065 |
|
1066 |
# or, more verbose |
1067 |
filter=only,level,warn |
1068 |
|
1069 |
=item C<1>..C<9>, a logging level name (C<error>, C<debug> etc.) |
1070 |
|
1071 |
A numeric loglevel or the name of a loglevel will be interpreted according |
1072 |
to the most recent C<only>, C<except> or C<level> directive. By default, |
1073 |
specifying a logging level enables that and any higher priority messages. |
1074 |
|
1075 |
=item C<+>I<context> |
1076 |
|
1077 |
Adds/attaches the named context as slave to the context. |
1078 |
|
1079 |
=item C<+> |
1080 |
|
1081 |
A line C<+> clears the slave list form the context. Anonymous (C<%name>) |
1082 |
contexts have no slaves by default, but package contexts have the parent |
1083 |
context as slave by default. |
1084 |
|
1085 |
Example: log messages from My::Module to a file, do not send them to the |
1086 |
default log collector. |
1087 |
|
1088 |
My::Module=+,file=/tmp/mymodulelog |
1089 |
|
1090 |
=back |
1091 |
|
1092 |
=cut |
1093 |
|
1094 |
for (my $spec = $ENV{PERL_ANYEVENT_LOG}) { |
1095 |
my %anon; |
1096 |
|
1097 |
my $pkg = sub { |
1098 |
$_[0] eq "log" ? $LOG |
1099 |
: $_[0] eq "filter" ? $FILTER |
1100 |
: $_[0] eq "collect" ? $COLLECT |
1101 |
: $_[0] =~ /^%(.+)$/ && $anon{$1} ||= ctx undef |
1102 |
: $_[0] =~ /^(.*?)(?:::)?$/ && ctx "$1" # egad :/ |
1103 |
}; |
1104 |
|
1105 |
while (/\G((?:[^:=]+|::|\\.)+)=/gc) { |
1106 |
my $ctx = $pkg->($1); |
1107 |
my $level = "level"; |
1108 |
|
1109 |
while (/\G((?:[^,:[:space:]]+|::|\\.)+)/gc) { |
1110 |
for ("$1") { |
1111 |
if ($_ eq "stderr" ) { $ctx->log_to_warn; |
1112 |
} elsif (/^file=(.+)/ ) { $ctx->log_to_file ("$1"); |
1113 |
} elsif (/^path=(.+)/ ) { $ctx->log_to_path ("$1"); |
1114 |
} elsif (/syslog(?:=(.*))?/ ) { require Sys::Syslog; $ctx->log_to_syslog (eval "package Sys::Syslog; $1"); |
1115 |
} elsif ($_ eq "nolog" ) { $ctx->log_cb (undef); |
1116 |
} elsif (/^\+(.+)$/ ) { $ctx->attach ($pkg->("$1")); |
1117 |
} elsif ($_ eq "+" ) { $ctx->slaves; |
1118 |
} elsif ($_ eq "off" or $_ eq "0") { $ctx->level (0); |
1119 |
} elsif ($_ eq "all" ) { $ctx->level ("all"); |
1120 |
} elsif ($_ eq "level" ) { $ctx->level ("all"); $level = "level"; |
1121 |
} elsif ($_ eq "only" ) { $ctx->level ("off"); $level = "enable"; |
1122 |
} elsif ($_ eq "except" ) { $ctx->level ("all"); $level = "disable"; |
1123 |
} elsif (/^\d$/ ) { $ctx->$level ($_); |
1124 |
} elsif (exists $STR2LEVEL{$_} ) { $ctx->$level ($_); |
1125 |
} else { die "PERL_ANYEVENT_LOG ($spec): parse error at '$_'\n"; |
1126 |
} |
1127 |
} |
1128 |
|
1129 |
/\G,/gc or last; |
1130 |
} |
1131 |
|
1132 |
/\G[:[:space:]]/gc or last; |
1133 |
} |
1134 |
|
1135 |
if (/\G(.+)/g) { |
1136 |
die "PERL_ANYEVENT_LOG ($spec): parse error at '$1'\n"; |
1137 |
} |
1138 |
} |
1139 |
|
1140 |
1; |
1141 |
|
1142 |
=head1 EXAMPLES |
1143 |
|
1144 |
This section shows some common configurations, both as code, and as |
1145 |
C<PERL_ANYEVENT_LOG> string. |
1146 |
|
1147 |
=over 4 |
1148 |
|
1149 |
=item Setting the global logging level. |
1150 |
|
1151 |
Either put C<PERL_ANYEVENT_VERBOSE=><number> into your environment before |
1152 |
running your program, use C<PERL_ANYEVENT_LOG> or modify the log level of |
1153 |
the root context at runtime: |
1154 |
|
1155 |
PERL_ANYEVENT_VERBOSE=5 ./myprog |
1156 |
|
1157 |
PERL_ANYEVENT_LOG=log=warn |
1158 |
|
1159 |
$AnyEvent::Log::FILTER->level ("warn"); |
1160 |
|
1161 |
=item Append all messages to a file instead of sending them to STDERR. |
1162 |
|
1163 |
This is affected by the global logging level. |
1164 |
|
1165 |
$AnyEvent::Log::LOG->log_to_file ($path); |
1166 |
|
1167 |
PERL_ANYEVENT_LOG=log=file=/some/path |
1168 |
|
1169 |
=item Write all messages with priority C<error> and higher to a file. |
1170 |
|
1171 |
This writes them only when the global logging level allows it, because |
1172 |
it is attached to the default context which is invoked I<after> global |
1173 |
filtering. |
1174 |
|
1175 |
$AnyEvent::Log::FILTER->attach |
1176 |
new AnyEvent::Log::Ctx log_to_file => $path); |
1177 |
|
1178 |
PERL_ANYEVENT_LOG=filter=+%filelogger:%filelogger=file=/some/path |
1179 |
|
1180 |
This writes them regardless of the global logging level, because it is |
1181 |
attached to the toplevel context, which receives all messages I<before> |
1182 |
the global filtering. |
1183 |
|
1184 |
$AnyEvent::Log::COLLECT->attach ( |
1185 |
new AnyEvent::Log::Ctx log_to_file => $path); |
1186 |
|
1187 |
PERL_ANYEVENT_LOG=%filelogger=file=/some/path:collect=+%filelogger |
1188 |
|
1189 |
In both cases, messages are still written to STDERR. |
1190 |
|
1191 |
=item Write trace messages (only) from L<AnyEvent::Debug> to the default logging target(s). |
1192 |
|
1193 |
Attach the C<$AnyEvent::Log::LOG> context to the C<AnyEvent::Debug> |
1194 |
context - this simply circumvents the global filtering for trace messages. |
1195 |
|
1196 |
my $debug = AnyEvent::Debug->AnyEvent::Log::ctx; |
1197 |
$debug->attach ($AnyEvent::Log::LOG); |
1198 |
|
1199 |
PERL_ANYEVENT_LOG=AnyEvent::Debug=+log |
1200 |
|
1201 |
This of course works for any package, not just L<AnyEvent::Debug>, but |
1202 |
assumes the log level for AnyEvent::Debug hasn't been changed from the |
1203 |
default. |
1204 |
|
1205 |
=back |
1206 |
|
1207 |
=head1 AUTHOR |
1208 |
|
1209 |
Marc Lehmann <schmorp@schmorp.de> |
1210 |
http://home.schmorp.de/ |
1211 |
|
1212 |
=cut |
1213 |
|