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 fatal => "No config found, cannot continue!"; # never returns |
12 |
AE::log alert => "The battery died!"; |
13 |
AE::log crit => "The battery temperature is too hot!"; |
14 |
AE::log error => "Division by zero attempted."; |
15 |
AE::log warn => "Couldn't delete the file."; |
16 |
AE::log note => "Wanted to create config, but config already exists."; |
17 |
AE::log info => "File soandso successfully deleted."; |
18 |
AE::log debug => "the function returned 3"; |
19 |
AE::log trace => "going to call function abc"; |
20 |
|
21 |
Log level overview: |
22 |
|
23 |
LVL NAME SYSLOG PERL NOTE |
24 |
1 fatal emerg exit system unusable, aborts program! |
25 |
2 alert failure in primary system |
26 |
3 critical crit failure in backup system |
27 |
4 error err die non-urgent program errors, a bug |
28 |
5 warn warning possible problem, not necessarily error |
29 |
6 note notice unusual conditions |
30 |
7 info normal messages, no action required |
31 |
8 debug debugging messages for development |
32 |
9 trace copious tracing output |
33 |
|
34 |
"Complex" uses (for speed sensitive code, e.g. trace/debug messages): |
35 |
|
36 |
use AnyEvent::Log; |
37 |
|
38 |
my $tracer = AnyEvent::Log::logger trace => \$my $trace; |
39 |
|
40 |
$tracer->("i am here") if $trace; |
41 |
$tracer->(sub { "lots of data: " . Dumper $self }) if $trace; |
42 |
|
43 |
Configuration (also look at the EXAMPLES section): |
44 |
|
45 |
# set logging for the current package to errors and higher only |
46 |
AnyEvent::Log::ctx->level ("error"); |
47 |
|
48 |
# set logging level to suppress anything below "notice" |
49 |
$AnyEvent::Log::FILTER->level ("notice"); |
50 |
|
51 |
# send all critical and higher priority messages to syslog, |
52 |
# regardless of (most) other settings |
53 |
$AnyEvent::Log::COLLECT->attach (new AnyEvent::Log::Ctx |
54 |
level => "critical", |
55 |
log_to_syslog => "user", |
56 |
); |
57 |
|
58 |
=head1 DESCRIPTION |
59 |
|
60 |
This module implements a relatively simple "logging framework". It doesn't |
61 |
attempt to be "the" logging solution or even "a" logging solution for |
62 |
AnyEvent - AnyEvent simply creates logging messages internally, and this |
63 |
module more or less exposes the mechanism, with some extra spiff to allow |
64 |
using it from other modules as well. |
65 |
|
66 |
Remember that the default verbosity level is C<4> (C<error>), so only |
67 |
errors and more important messages will be logged, unless you set |
68 |
C<PERL_ANYEVENT_VERBOSE> to a higher number before starting your program |
69 |
(C<AE_VERBOSE=5> is recommended during development), or change the logging |
70 |
level at runtime with something like: |
71 |
|
72 |
use AnyEvent::Log; |
73 |
$AnyEvent::Log::FILTER->level ("info"); |
74 |
|
75 |
The design goal behind this module was to keep it simple (and small), |
76 |
but make it powerful enough to be potentially useful for any module, |
77 |
and extensive enough for the most common tasks, such as logging to |
78 |
multiple targets, or being able to log into a database. |
79 |
|
80 |
The module is also usable before AnyEvent itself is initialised, in which |
81 |
case some of the functionality might be reduced. |
82 |
|
83 |
The amount of documentation might indicate otherwise, but the runtime part |
84 |
of the module is still just below 300 lines of code. |
85 |
|
86 |
=head1 LOGGING LEVELS |
87 |
|
88 |
Logging levels in this module range from C<1> (highest priority) to C<9> |
89 |
(lowest priority). Note that the lowest numerical value is the highest |
90 |
priority, so when this document says "higher priority" it means "lower |
91 |
numerical value". |
92 |
|
93 |
Instead of specifying levels by name you can also specify them by aliases: |
94 |
|
95 |
LVL NAME SYSLOG PERL NOTE |
96 |
1 fatal emerg exit system unusable, aborts program! |
97 |
2 alert failure in primary system |
98 |
3 critical crit failure in backup system |
99 |
4 error err die non-urgent program errors, a bug |
100 |
5 warn warning possible problem, not necessarily error |
101 |
6 note notice unusual conditions |
102 |
7 info normal messages, no action required |
103 |
8 debug debugging messages for development |
104 |
9 trace copious tracing output |
105 |
|
106 |
As you can see, some logging levels have multiple aliases - the first one |
107 |
is the "official" name, the second one the "syslog" name (if it differs) |
108 |
and the third one the "perl" name, suggesting (only!) that you log C<die> |
109 |
messages at C<error> priority. The NOTE column tries to provide some |
110 |
rationale on how to chose a logging level. |
111 |
|
112 |
As a rough guideline, levels 1..3 are primarily meant for users of the |
113 |
program (admins, staff), and are the only ones logged to STDERR by |
114 |
default. Levels 4..6 are meant for users and developers alike, while |
115 |
levels 7..9 are usually meant for developers. |
116 |
|
117 |
You can normally only log a message once at highest priority level (C<1>, |
118 |
C<fatal>), because logging a fatal message will also quit the program - so |
119 |
use it sparingly :) |
120 |
|
121 |
For example, a program that finds an unknown switch on the commandline |
122 |
might well use a fatal logging level to tell users about it - the "system" |
123 |
in this case would be the program, or module. |
124 |
|
125 |
Some methods also offer some extra levels, such as C<0>, C<off>, C<none> |
126 |
or C<all> - these are only valid for the methods that documented them. |
127 |
|
128 |
=head1 LOGGING FUNCTIONS |
129 |
|
130 |
The following functions allow you to log messages. They always use the |
131 |
caller's package as a "logging context". Also, the main logging function, |
132 |
C<log>, is aliased to C<AnyEvent::log> and C<AE::log> when the C<AnyEvent> |
133 |
module is loaded. |
134 |
|
135 |
=over 4 |
136 |
|
137 |
=cut |
138 |
|
139 |
package AnyEvent::Log; |
140 |
|
141 |
use Carp (); |
142 |
use POSIX (); |
143 |
|
144 |
# layout of a context |
145 |
# 0 1 2 3 4, 5 |
146 |
# [$title, $level, %$slaves, &$logcb, &$fmtcb, $cap] |
147 |
|
148 |
use AnyEvent (); BEGIN { AnyEvent::common_sense } |
149 |
#use AnyEvent::Util (); need to load this in a delayed fashion, as it uses AE::log |
150 |
|
151 |
our $VERSION = $AnyEvent::VERSION; |
152 |
|
153 |
our ($COLLECT, $FILTER, $LOG); |
154 |
|
155 |
our ($now_int, $now_str1, $now_str2); |
156 |
|
157 |
# Format Time, not public - yet? |
158 |
sub format_time($) { |
159 |
my $i = int $_[0]; |
160 |
my $f = sprintf "%06d", 1e6 * ($_[0] - $i); |
161 |
|
162 |
($now_int, $now_str1, $now_str2) = ($i, split /\x01/, POSIX::strftime "%Y-%m-%d %H:%M:%S.\x01 %z", localtime $i) |
163 |
if $now_int != $i; |
164 |
|
165 |
"$now_str1$f$now_str2" |
166 |
} |
167 |
|
168 |
our %CTX; # all package contexts |
169 |
|
170 |
# creates a default package context object for the given package |
171 |
sub _pkg_ctx($) { |
172 |
my $ctx = bless [$_[0], (1 << 10) - 1 - 1, {}], "AnyEvent::Log::Ctx"; |
173 |
|
174 |
# link "parent" package |
175 |
my $parent = $_[0] =~ /^(.+)::/ |
176 |
? $CTX{$1} ||= &_pkg_ctx ("$1") |
177 |
: $COLLECT; |
178 |
|
179 |
$ctx->[2]{$parent+0} = $parent; |
180 |
|
181 |
$ctx |
182 |
} |
183 |
|
184 |
=item AnyEvent::Log::log $level, $msg[, @args] |
185 |
|
186 |
Requests logging of the given C<$msg> with the given log level, and |
187 |
returns true if the message was logged I<somewhere>. |
188 |
|
189 |
For loglevel C<fatal>, the program will abort. |
190 |
|
191 |
If only a C<$msg> is given, it is logged as-is. With extra C<@args>, the |
192 |
C<$msg> is interpreted as an sprintf format string. |
193 |
|
194 |
The C<$msg> should not end with C<\n>, but may if that is convenient for |
195 |
you. Also, multiline messages are handled properly. |
196 |
|
197 |
Last not least, C<$msg> might be a code reference, in which case it is |
198 |
supposed to return the message. It will be called only then the message |
199 |
actually gets logged, which is useful if it is costly to create the |
200 |
message in the first place. |
201 |
|
202 |
This function takes care of saving and restoring C<$!> and C<$@>, so you |
203 |
don't have to. |
204 |
|
205 |
Whether the given message will be logged depends on the maximum log level |
206 |
and the caller's package. The return value can be used to ensure that |
207 |
messages or not "lost" - for example, when L<AnyEvent::Debug> detects a |
208 |
runtime error it tries to log it at C<die> level, but if that message is |
209 |
lost it simply uses warn. |
210 |
|
211 |
Note that you can (and should) call this function as C<AnyEvent::log> or |
212 |
C<AE::log>, without C<use>-ing this module if possible (i.e. you don't |
213 |
need any additional functionality), as those functions will load the |
214 |
logging module on demand only. They are also much shorter to write. |
215 |
|
216 |
Also, if you optionally generate a lot of debug messages (such as when |
217 |
tracing some code), you should look into using a logger callback and a |
218 |
boolean enabler (see C<logger>, below). |
219 |
|
220 |
Example: log something at error level. |
221 |
|
222 |
AE::log error => "something"; |
223 |
|
224 |
Example: use printf-formatting. |
225 |
|
226 |
AE::log info => "%5d %-10.10s %s", $index, $category, $msg; |
227 |
|
228 |
Example: only generate a costly dump when the message is actually being logged. |
229 |
|
230 |
AE::log debug => sub { require Data::Dump; Data::Dump::dump \%cache }; |
231 |
|
232 |
=cut |
233 |
|
234 |
# also allow syslog equivalent names |
235 |
our %STR2LEVEL = ( |
236 |
fatal => 1, emerg => 1, exit => 1, |
237 |
alert => 2, |
238 |
critical => 3, crit => 3, |
239 |
error => 4, err => 4, die => 4, |
240 |
warn => 5, warning => 5, |
241 |
note => 6, notice => 6, |
242 |
info => 7, |
243 |
debug => 8, |
244 |
trace => 9, |
245 |
); |
246 |
|
247 |
our $TIME_EXACT; |
248 |
|
249 |
sub exact_time($) { |
250 |
$TIME_EXACT = shift; |
251 |
*_ts = $AnyEvent::MODEL |
252 |
? $TIME_EXACT ? \&AE::now : \&AE::time |
253 |
: sub () { $TIME_EXACT ? do { require Time::HiRes; Time::HiRes::time () } : time }; |
254 |
} |
255 |
|
256 |
BEGIN { |
257 |
exact_time 0; |
258 |
} |
259 |
|
260 |
AnyEvent::post_detect { |
261 |
exact_time $TIME_EXACT; |
262 |
}; |
263 |
|
264 |
our @LEVEL2STR = qw(0 fatal alert crit error warn note info debug trace); |
265 |
|
266 |
# time, ctx, level, msg |
267 |
sub default_format($$$$) { |
268 |
my $ts = format_time $_[0]; |
269 |
my $ct = " "; |
270 |
|
271 |
my @res; |
272 |
|
273 |
for (split /\n/, sprintf "%-5s %s: %s", $LEVEL2STR[$_[2]], $_[1][0], $_[3]) { |
274 |
push @res, "$ts$ct$_\n"; |
275 |
$ct = " + "; |
276 |
} |
277 |
|
278 |
join "", @res |
279 |
} |
280 |
|
281 |
sub fatal_exit() { |
282 |
exit 1; |
283 |
} |
284 |
|
285 |
sub _log { |
286 |
my ($ctx, $level, $format, @args) = @_; |
287 |
|
288 |
$level = $level > 0 && $level <= 9 |
289 |
? $level+0 |
290 |
: $STR2LEVEL{$level} || Carp::croak "$level: not a valid logging level, caught"; |
291 |
|
292 |
my $mask = 1 << $level; |
293 |
|
294 |
my ($success, %seen, @ctx, $now, @fmt); |
295 |
|
296 |
do |
297 |
{ |
298 |
# if !ref, then it's a level number |
299 |
if (!ref $ctx) { |
300 |
$level = $ctx; |
301 |
} elsif ($ctx->[1] & $mask and !$seen{$ctx+0}++) { |
302 |
# logging/recursing into this context |
303 |
|
304 |
# level cap |
305 |
if ($ctx->[5] > $level) { |
306 |
push @ctx, $level; # restore level when going up in tree |
307 |
$level = $ctx->[5]; |
308 |
} |
309 |
|
310 |
# log if log cb |
311 |
if ($ctx->[3]) { |
312 |
# logging target found |
313 |
|
314 |
local ($!, $@); |
315 |
|
316 |
# now get raw message, unless we have it already |
317 |
unless ($now) { |
318 |
$format = $format->() if ref $format; |
319 |
$format = sprintf $format, @args if @args; |
320 |
$format =~ s/\n$//; |
321 |
$now = _ts; |
322 |
}; |
323 |
|
324 |
# format msg |
325 |
my $str = $ctx->[4] |
326 |
? $ctx->[4]($now, $_[0], $level, $format) |
327 |
: ($fmt[$level] ||= default_format $now, $_[0], $level, $format); |
328 |
|
329 |
$success = 1; |
330 |
|
331 |
$ctx->[3]($str) |
332 |
or push @ctx, values %{ $ctx->[2] }; # not consumed - propagate |
333 |
} else { |
334 |
push @ctx, values %{ $ctx->[2] }; # not masked - propagate |
335 |
} |
336 |
} |
337 |
} |
338 |
while $ctx = pop @ctx; |
339 |
|
340 |
fatal_exit if $level <= 1; |
341 |
|
342 |
$success |
343 |
} |
344 |
|
345 |
sub log($$;@) { |
346 |
_log |
347 |
$CTX{ (caller)[0] } ||= _pkg_ctx +(caller)[0], |
348 |
@_; |
349 |
} |
350 |
|
351 |
=item $logger = AnyEvent::Log::logger $level[, \$enabled] |
352 |
|
353 |
Creates a code reference that, when called, acts as if the |
354 |
C<AnyEvent::Log::log> function was called at this point with the given |
355 |
level. C<$logger> is passed a C<$msg> and optional C<@args>, just as with |
356 |
the C<AnyEvent::Log::log> function: |
357 |
|
358 |
my $debug_log = AnyEvent::Log::logger "debug"; |
359 |
|
360 |
$debug_log->("debug here"); |
361 |
$debug_log->("%06d emails processed", 12345); |
362 |
$debug_log->(sub { $obj->as_string }); |
363 |
|
364 |
The idea behind this function is to decide whether to log before actually |
365 |
logging - when the C<logger> function is called once, but the returned |
366 |
logger callback often, then this can be a tremendous speed win. |
367 |
|
368 |
Despite this speed advantage, changes in logging configuration will |
369 |
still be reflected by the logger callback, even if configuration changes |
370 |
I<after> it was created. |
371 |
|
372 |
To further speed up logging, you can bind a scalar variable to the logger, |
373 |
which contains true if the logger should be called or not - if it is |
374 |
false, calling the logger can be safely skipped. This variable will be |
375 |
updated as long as C<$logger> is alive. |
376 |
|
377 |
Full example: |
378 |
|
379 |
# near the init section |
380 |
use AnyEvent::Log; |
381 |
|
382 |
my $debug_log = AnyEvent:Log::logger debug => \my $debug; |
383 |
|
384 |
# and later in your program |
385 |
$debug_log->("yo, stuff here") if $debug; |
386 |
|
387 |
$debug and $debug_log->("123"); |
388 |
|
389 |
=cut |
390 |
|
391 |
our %LOGGER; |
392 |
|
393 |
# re-assess logging status for all loggers |
394 |
sub _reassess { |
395 |
local $SIG{__DIE__}; |
396 |
my $die = sub { die }; |
397 |
|
398 |
for (@_ ? $LOGGER{$_[0]} : values %LOGGER) { |
399 |
my ($ctx, $level, $renabled) = @$_; |
400 |
|
401 |
# to detect whether a message would be logged, we actually |
402 |
# try to log one and die. this isn't fast, but we can be |
403 |
# sure that the logging decision is correct :) |
404 |
|
405 |
$$renabled = !eval { |
406 |
_log $ctx, $level, $die; |
407 |
|
408 |
1 |
409 |
}; |
410 |
} |
411 |
} |
412 |
|
413 |
sub _logger { |
414 |
my ($ctx, $level, $renabled) = @_; |
415 |
|
416 |
$$renabled = 1; |
417 |
|
418 |
my $logger = [$ctx, $level, $renabled]; |
419 |
|
420 |
$LOGGER{$logger+0} = $logger; |
421 |
|
422 |
_reassess $logger+0; |
423 |
|
424 |
require AnyEvent::Util unless $AnyEvent::Util::VERSION; |
425 |
my $guard = AnyEvent::Util::guard (sub { |
426 |
# "clean up" |
427 |
delete $LOGGER{$logger+0}; |
428 |
}); |
429 |
|
430 |
sub { |
431 |
$guard if 0; # keep guard alive, but don't cause runtime overhead |
432 |
|
433 |
_log $ctx, $level, @_ |
434 |
if $$renabled; |
435 |
} |
436 |
} |
437 |
|
438 |
sub logger($;$) { |
439 |
_logger |
440 |
$CTX{ (caller)[0] } ||= _pkg_ctx +(caller)[0], |
441 |
@_ |
442 |
} |
443 |
|
444 |
=item AnyEvent::Log::exact_time $on |
445 |
|
446 |
By default, C<AnyEvent::Log> will use C<AE::now>, i.e. the cached |
447 |
eventloop time, for the log timestamps. After calling this function with a |
448 |
true value it will instead resort to C<AE::time>, i.e. fetch the current |
449 |
time on each log message. This only makes a difference for event loops |
450 |
that actually cache the time (such as L<EV> or L<AnyEvent::Loop>). |
451 |
|
452 |
This setting can be changed at any time by calling this function. |
453 |
|
454 |
Since C<AnyEvent::Log> has to work even before the L<AnyEvent> has been |
455 |
initialised, this switch will also decide whether to use C<CORE::time> or |
456 |
C<Time::HiRes::time> when logging a message before L<AnyEvent> becomes |
457 |
available. |
458 |
|
459 |
=item AnyEvent::Log::format_time $timestamp |
460 |
|
461 |
Formats a timestamp as returned by C<< AnyEvent->now >> or C<< |
462 |
AnyEvent->time >> or many other functions in the same way as |
463 |
C<AnyEvent::Log> does. |
464 |
|
465 |
In your main program (as opposed to in your module) you can override |
466 |
the default timestamp display format by loading this module and then |
467 |
redefining this function. |
468 |
|
469 |
Most commonly, this function can be used in formatting callbacks. |
470 |
|
471 |
=item AnyEvent::Log::default_format $time, $ctx, $level, $msg |
472 |
|
473 |
Format a log message using the given timestamp, logging context, log level |
474 |
and log message. |
475 |
|
476 |
This is the formatting function used to format messages when no custom |
477 |
function is provided. |
478 |
|
479 |
In your main program (as opposed to in your module) you can override the |
480 |
default message format by loading this module and then redefining this |
481 |
function. |
482 |
|
483 |
=item AnyEvent::Log::fatal_exit |
484 |
|
485 |
This is the function that is called after logging a C<fatal> log |
486 |
message. It must not return. |
487 |
|
488 |
The default implementation simply calls C<exit 1>. |
489 |
|
490 |
In your main program (as opposed to in your module) you can override |
491 |
the fatal exit function by loading this module and then redefining this |
492 |
function. Make sure you don't return. |
493 |
|
494 |
=back |
495 |
|
496 |
=head1 LOGGING CONTEXTS |
497 |
|
498 |
This module associates every log message with a so-called I<logging |
499 |
context>, based on the package of the caller. Every perl package has its |
500 |
own logging context. |
501 |
|
502 |
A logging context has three major responsibilities: filtering, logging and |
503 |
propagating the message. |
504 |
|
505 |
For the first purpose, filtering, each context has a set of logging |
506 |
levels, called the log level mask. Messages not in the set will be ignored |
507 |
by this context (masked). |
508 |
|
509 |
For logging, the context stores a formatting callback (which takes the |
510 |
timestamp, context, level and string message and formats it in the way |
511 |
it should be logged) and a logging callback (which is responsible for |
512 |
actually logging the formatted message and telling C<AnyEvent::Log> |
513 |
whether it has consumed the message, or whether it should be propagated). |
514 |
|
515 |
For propagation, a context can have any number of attached I<slave |
516 |
contexts>. Any message that is neither masked by the logging mask nor |
517 |
masked by the logging callback returning true will be passed to all slave |
518 |
contexts. |
519 |
|
520 |
Each call to a logging function will log the message at most once per |
521 |
context, so it does not matter (much) if there are cycles or if the |
522 |
message can arrive at the same context via multiple paths. |
523 |
|
524 |
=head2 DEFAULTS |
525 |
|
526 |
By default, all logging contexts have an full set of log levels ("all"), a |
527 |
disabled logging callback and the default formatting callback. |
528 |
|
529 |
Package contexts have the package name as logging title by default. |
530 |
|
531 |
They have exactly one slave - the context of the "parent" package. The |
532 |
parent package is simply defined to be the package name without the last |
533 |
component, i.e. C<AnyEvent::Debug::Wrapped> becomes C<AnyEvent::Debug>, |
534 |
and C<AnyEvent> becomes ... C<$AnyEvent::Log::COLLECT> which is the |
535 |
exception of the rule - just like the "parent" of any single-component |
536 |
package name in Perl is C<main>, the default slave of any top-level |
537 |
package context is C<$AnyEvent::Log::COLLECT>. |
538 |
|
539 |
Since perl packages form only an approximate hierarchy, this slave |
540 |
context can of course be removed. |
541 |
|
542 |
All other (anonymous) contexts have no slaves and an empty title by |
543 |
default. |
544 |
|
545 |
When the module is loaded it creates the C<$AnyEvent::Log::LOG> logging |
546 |
context that simply logs everything via C<warn>, without propagating |
547 |
anything anywhere by default. The purpose of this context is to provide |
548 |
a convenient place to override the global logging target or to attach |
549 |
additional log targets. It's not meant for filtering. |
550 |
|
551 |
It then creates the C<$AnyEvent::Log::FILTER> context whose |
552 |
purpose is to suppress all messages with priority higher |
553 |
than C<$ENV{PERL_ANYEVENT_VERBOSE}>. It then attached the |
554 |
C<$AnyEvent::Log::LOG> context to it. The purpose of the filter context |
555 |
is to simply provide filtering according to some global log level. |
556 |
|
557 |
Finally it creates the top-level package context C<$AnyEvent::Log::COLLECT> |
558 |
and attaches the C<$AnyEvent::Log::FILTER> context to it, but otherwise |
559 |
leaves it at default config. Its purpose is simply to collect all log |
560 |
messages system-wide. |
561 |
|
562 |
The hierarchy is then: |
563 |
|
564 |
any package, eventually -> $COLLECT -> $FILTER -> $LOG |
565 |
|
566 |
The effect of all this is that log messages, by default, wander up to the |
567 |
C<$AnyEvent::Log::COLLECT> context where all messages normally end up, |
568 |
from there to C<$AnyEvent::Log::FILTER> where log messages with lower |
569 |
priority then C<$ENV{PERL_ANYEVENT_VERBOSE}> will be filtered out and then |
570 |
to the C<$AnyEvent::Log::LOG> context to be passed to C<warn>. |
571 |
|
572 |
This makes it easy to set a global logging level (by modifying $FILTER), |
573 |
but still allow other contexts to send, for example, their debug and trace |
574 |
messages to the $LOG target despite the global logging level, or to attach |
575 |
additional log targets that log messages, regardless of the global logging |
576 |
level. |
577 |
|
578 |
It also makes it easy to modify the default warn-logger ($LOG) to |
579 |
something that logs to a file, or to attach additional logging targets |
580 |
(such as loggign to a file) by attaching it to $FILTER. |
581 |
|
582 |
=head2 CREATING/FINDING/DESTROYING CONTEXTS |
583 |
|
584 |
=over 4 |
585 |
|
586 |
=item $ctx = AnyEvent::Log::ctx [$pkg] |
587 |
|
588 |
This function creates or returns a logging context (which is an object). |
589 |
|
590 |
If a package name is given, then the context for that packlage is |
591 |
returned. If it is called without any arguments, then the context for the |
592 |
callers package is returned (i.e. the same context as a C<AE::log> call |
593 |
would use). |
594 |
|
595 |
If C<undef> is given, then it creates a new anonymous context that is not |
596 |
tied to any package and is destroyed when no longer referenced. |
597 |
|
598 |
=cut |
599 |
|
600 |
sub ctx(;$) { |
601 |
my $pkg = @_ ? shift : (caller)[0]; |
602 |
|
603 |
ref $pkg |
604 |
? $pkg |
605 |
: defined $pkg |
606 |
? $CTX{$pkg} ||= AnyEvent::Log::_pkg_ctx $pkg |
607 |
: bless [undef, (1 << 10) - 1 - 1], "AnyEvent::Log::Ctx" |
608 |
} |
609 |
|
610 |
=item AnyEvent::Log::reset |
611 |
|
612 |
Resets all package contexts and recreates the default hierarchy if |
613 |
necessary, i.e. resets the logging subsystem to defaults, as much as |
614 |
possible. This process keeps references to contexts held by other parts of |
615 |
the program intact. |
616 |
|
617 |
This can be used to implement config-file (re-)loading: before loading a |
618 |
configuration, reset all contexts. |
619 |
|
620 |
=cut |
621 |
|
622 |
our $ORIG_VERBOSE = $AnyEvent::VERBOSE; |
623 |
$AnyEvent::VERBOSE = 9; |
624 |
|
625 |
sub reset { |
626 |
# hard to kill complex data structures |
627 |
# we "recreate" all package loggers and reset the hierarchy |
628 |
while (my ($k, $v) = each %CTX) { |
629 |
@$v = ($k, (1 << 10) - 1 - 1, { }); |
630 |
|
631 |
$v->attach ($k =~ /^(.+)::/ ? $CTX{$1} : $AnyEvent::Log::COLLECT); |
632 |
} |
633 |
|
634 |
@$_ = ($_->[0], (1 << 10) - 1 - 1) |
635 |
for $LOG, $FILTER, $COLLECT; |
636 |
|
637 |
#$LOG->slaves; |
638 |
$LOG->title ('$AnyEvent::Log::LOG'); |
639 |
$LOG->log_to_warn; |
640 |
|
641 |
$FILTER->slaves ($LOG); |
642 |
$FILTER->title ('$AnyEvent::Log::FILTER'); |
643 |
$FILTER->level ($ORIG_VERBOSE); |
644 |
|
645 |
$COLLECT->slaves ($FILTER); |
646 |
$COLLECT->title ('$AnyEvent::Log::COLLECT'); |
647 |
|
648 |
_reassess; |
649 |
} |
650 |
|
651 |
# override AE::log/logger |
652 |
*AnyEvent::log = *AE::log = \&log; |
653 |
*AnyEvent::logger = *AE::logger = \&logger; |
654 |
|
655 |
# convert AnyEvent loggers to AnyEvent::Log loggers |
656 |
$_->[0] = ctx $_->[0] # convert "pkg" to "ctx" |
657 |
for values %LOGGER; |
658 |
|
659 |
# create the default logger contexts |
660 |
$LOG = ctx undef; |
661 |
$FILTER = ctx undef; |
662 |
$COLLECT = ctx undef; |
663 |
|
664 |
AnyEvent::Log::reset; |
665 |
|
666 |
# hello, CPAN, please catch me |
667 |
package AnyEvent::Log::LOG; |
668 |
package AE::Log::LOG; |
669 |
package AnyEvent::Log::FILTER; |
670 |
package AE::Log::FILTER; |
671 |
package AnyEvent::Log::COLLECT; |
672 |
package AE::Log::COLLECT; |
673 |
|
674 |
package AnyEvent::Log::Ctx; |
675 |
|
676 |
=item $ctx = new AnyEvent::Log::Ctx methodname => param... |
677 |
|
678 |
This is a convenience constructor that makes it simpler to construct |
679 |
anonymous logging contexts. |
680 |
|
681 |
Each key-value pair results in an invocation of the method of the same |
682 |
name as the key with the value as parameter, unless the value is an |
683 |
arrayref, in which case it calls the method with the contents of the |
684 |
array. The methods are called in the same order as specified. |
685 |
|
686 |
Example: create a new logging context and set both the default logging |
687 |
level, some slave contexts and a logging callback. |
688 |
|
689 |
$ctx = new AnyEvent::Log::Ctx |
690 |
title => "dubious messages", |
691 |
level => "error", |
692 |
log_cb => sub { print STDOUT shift; 0 }, |
693 |
slaves => [$ctx1, $ctx, $ctx2], |
694 |
; |
695 |
|
696 |
=back |
697 |
|
698 |
=cut |
699 |
|
700 |
sub new { |
701 |
my $class = shift; |
702 |
|
703 |
my $ctx = AnyEvent::Log::ctx undef; |
704 |
|
705 |
while (@_) { |
706 |
my ($k, $v) = splice @_, 0, 2; |
707 |
$ctx->$k (ref $v eq "ARRAY" ? @$v : $v); |
708 |
} |
709 |
|
710 |
bless $ctx, $class # do we really support subclassing, hmm? |
711 |
} |
712 |
|
713 |
|
714 |
=head2 CONFIGURING A LOG CONTEXT |
715 |
|
716 |
The following methods can be used to configure the logging context. |
717 |
|
718 |
=over 4 |
719 |
|
720 |
=item $ctx->title ([$new_title]) |
721 |
|
722 |
Returns the title of the logging context - this is the package name, for |
723 |
package contexts, and a user defined string for all others. |
724 |
|
725 |
If C<$new_title> is given, then it replaces the package name or title. |
726 |
|
727 |
=cut |
728 |
|
729 |
sub title { |
730 |
$_[0][0] = $_[1] if @_ > 1; |
731 |
$_[0][0] |
732 |
} |
733 |
|
734 |
=back |
735 |
|
736 |
=head3 LOGGING LEVELS |
737 |
|
738 |
The following methods deal with the logging level set associated with the |
739 |
log context. |
740 |
|
741 |
The most common method to use is probably C<< $ctx->level ($level) >>, |
742 |
which configures the specified and any higher priority levels. |
743 |
|
744 |
All functions which accept a list of levels also accept the special string |
745 |
C<all> which expands to all logging levels. |
746 |
|
747 |
=over 4 |
748 |
|
749 |
=item $ctx->levels ($level[, $level...) |
750 |
|
751 |
Enables logging for the given levels and disables it for all others. |
752 |
|
753 |
=item $ctx->level ($level) |
754 |
|
755 |
Enables logging for the given level and all lower level (higher priority) |
756 |
ones. In addition to normal logging levels, specifying a level of C<0> or |
757 |
C<off> disables all logging for this level. |
758 |
|
759 |
Example: log warnings, errors and higher priority messages. |
760 |
|
761 |
$ctx->level ("warn"); |
762 |
$ctx->level (5); # same thing, just numeric |
763 |
|
764 |
=item $ctx->enable ($level[, $level...]) |
765 |
|
766 |
Enables logging for the given levels, leaving all others unchanged. |
767 |
|
768 |
=item $ctx->disable ($level[, $level...]) |
769 |
|
770 |
Disables logging for the given levels, leaving all others unchanged. |
771 |
|
772 |
=item $ctx->cap ($level) |
773 |
|
774 |
Caps the maximum priority to the given level, for all messages logged |
775 |
to, or passing through, this context. That is, while this doesn't affect |
776 |
whether a message is logged or passed on, the maximum priority of messages |
777 |
will be limited to the specified level - messages with a higher priority |
778 |
will be set to the specified priority. |
779 |
|
780 |
Another way to view this is that C<< ->level >> filters out messages with |
781 |
a too low priority, while C<< ->cap >> modifies messages with a too high |
782 |
priority. |
783 |
|
784 |
This is useful when different log targets have different interpretations |
785 |
of priority. For example, for a specific command line program, a wrong |
786 |
command line switch might well result in a C<fatal> log message, while the |
787 |
same message, logged to syslog, is likely I<not> fatal to the system or |
788 |
syslog facility as a whole, but more likely a mere C<error>. |
789 |
|
790 |
This can be modeled by having a stderr logger that logs messages "as-is" |
791 |
and a syslog logger that logs messages with a level cap of, say, C<error>, |
792 |
or, for truly system-critical components, actually C<critical>. |
793 |
|
794 |
=cut |
795 |
|
796 |
sub _lvl_lst { |
797 |
map { |
798 |
$_ > 0 && $_ <= 9 ? $_+0 |
799 |
: $_ eq "all" ? (1 .. 9) |
800 |
: $STR2LEVEL{$_} || Carp::croak "$_: not a valid logging level, caught" |
801 |
} @_ |
802 |
} |
803 |
|
804 |
sub _lvl { |
805 |
$_[0] =~ /^(?:0|off|none)$/ ? 0 : (_lvl_lst $_[0])[-1] |
806 |
} |
807 |
|
808 |
our $NOP_CB = sub { 0 }; |
809 |
|
810 |
sub levels { |
811 |
my $ctx = shift; |
812 |
$ctx->[1] = 0; |
813 |
$ctx->[1] |= 1 << $_ |
814 |
for &_lvl_lst; |
815 |
AnyEvent::Log::_reassess; |
816 |
} |
817 |
|
818 |
sub level { |
819 |
my $ctx = shift; |
820 |
$ctx->[1] = ((1 << &_lvl) - 1) << 1; |
821 |
AnyEvent::Log::_reassess; |
822 |
} |
823 |
|
824 |
sub enable { |
825 |
my $ctx = shift; |
826 |
$ctx->[1] |= 1 << $_ |
827 |
for &_lvl_lst; |
828 |
AnyEvent::Log::_reassess; |
829 |
} |
830 |
|
831 |
sub disable { |
832 |
my $ctx = shift; |
833 |
$ctx->[1] &= ~(1 << $_) |
834 |
for &_lvl_lst; |
835 |
AnyEvent::Log::_reassess; |
836 |
} |
837 |
|
838 |
sub cap { |
839 |
my $ctx = shift; |
840 |
$ctx->[5] = &_lvl; |
841 |
} |
842 |
|
843 |
=back |
844 |
|
845 |
=head3 SLAVE CONTEXTS |
846 |
|
847 |
The following methods attach and detach another logging context to a |
848 |
logging context. |
849 |
|
850 |
Log messages are propagated to all slave contexts, unless the logging |
851 |
callback consumes the message. |
852 |
|
853 |
=over 4 |
854 |
|
855 |
=item $ctx->attach ($ctx2[, $ctx3...]) |
856 |
|
857 |
Attaches the given contexts as slaves to this context. It is not an error |
858 |
to add a context twice (the second add will be ignored). |
859 |
|
860 |
A context can be specified either as package name or as a context object. |
861 |
|
862 |
=item $ctx->detach ($ctx2[, $ctx3...]) |
863 |
|
864 |
Removes the given slaves from this context - it's not an error to attempt |
865 |
to remove a context that hasn't been added. |
866 |
|
867 |
A context can be specified either as package name or as a context object. |
868 |
|
869 |
=item $ctx->slaves ($ctx2[, $ctx3...]) |
870 |
|
871 |
Replaces all slaves attached to this context by the ones given. |
872 |
|
873 |
=cut |
874 |
|
875 |
sub attach { |
876 |
my $ctx = shift; |
877 |
|
878 |
$ctx->[2]{$_+0} = $_ |
879 |
for map { AnyEvent::Log::ctx $_ } @_; |
880 |
} |
881 |
|
882 |
sub detach { |
883 |
my $ctx = shift; |
884 |
|
885 |
delete $ctx->[2]{$_+0} |
886 |
for map { AnyEvent::Log::ctx $_ } @_; |
887 |
} |
888 |
|
889 |
sub slaves { |
890 |
undef $_[0][2]; |
891 |
&attach; |
892 |
} |
893 |
|
894 |
=back |
895 |
|
896 |
=head3 LOG TARGETS |
897 |
|
898 |
The following methods configure how the logging context actually does |
899 |
the logging (which consists of formatting the message and printing it or |
900 |
whatever it wants to do with it). |
901 |
|
902 |
=over 4 |
903 |
|
904 |
=item $ctx->log_cb ($cb->($str)) |
905 |
|
906 |
Replaces the logging callback on the context (C<undef> disables the |
907 |
logging callback). |
908 |
|
909 |
The logging callback is responsible for handling formatted log messages |
910 |
(see C<fmt_cb> below) - normally simple text strings that end with a |
911 |
newline (and are possibly multiline themselves). |
912 |
|
913 |
It also has to return true iff it has consumed the log message, and false |
914 |
if it hasn't. Consuming a message means that it will not be sent to any |
915 |
slave context. When in doubt, return C<0> from your logging callback. |
916 |
|
917 |
Example: a very simple logging callback, simply dump the message to STDOUT |
918 |
and do not consume it. |
919 |
|
920 |
$ctx->log_cb (sub { print STDERR shift; 0 }); |
921 |
|
922 |
You can filter messages by having a log callback that simply returns C<1> |
923 |
and does not do anything with the message, but this counts as "message |
924 |
being logged" and might not be very efficient. |
925 |
|
926 |
Example: propagate all messages except for log levels "debug" and |
927 |
"trace". The messages will still be generated, though, which can slow down |
928 |
your program. |
929 |
|
930 |
$ctx->levels ("debug", "trace"); |
931 |
$ctx->log_cb (sub { 1 }); # do not log, but eat debug and trace messages |
932 |
|
933 |
=item $ctx->fmt_cb ($fmt_cb->($timestamp, $orig_ctx, $level, $message)) |
934 |
|
935 |
Replaces the formatting callback on the context (C<undef> restores the |
936 |
default formatter). |
937 |
|
938 |
The callback is passed the (possibly fractional) timestamp, the original |
939 |
logging context (object, not title), the (numeric) logging level and |
940 |
the raw message string and needs to return a formatted log message. In |
941 |
most cases this will be a string, but it could just as well be an array |
942 |
reference that just stores the values. |
943 |
|
944 |
If, for some reason, you want to use C<caller> to find out more about the |
945 |
logger then you should walk up the call stack until you are no longer |
946 |
inside the C<AnyEvent::Log> package. |
947 |
|
948 |
To implement your own logging callback, you might find the |
949 |
C<AnyEvent::Log::format_time> and C<AnyEvent::Log::default_format> |
950 |
functions useful. |
951 |
|
952 |
Example: format the message just as AnyEvent::Log would, by letting |
953 |
AnyEvent::Log do the work. This is a good basis to design a formatting |
954 |
callback that only changes minor aspects of the formatting. |
955 |
|
956 |
$ctx->fmt_cb (sub { |
957 |
my ($time, $ctx, $lvl, $msg) = @_; |
958 |
|
959 |
AnyEvent::Log::default_format $time, $ctx, $lvl, $msg |
960 |
}); |
961 |
|
962 |
Example: format just the raw message, with numeric log level in angle |
963 |
brackets. |
964 |
|
965 |
$ctx->fmt_cb (sub { |
966 |
my ($time, $ctx, $lvl, $msg) = @_; |
967 |
|
968 |
"<$lvl>$msg\n" |
969 |
}); |
970 |
|
971 |
Example: return an array reference with just the log values, and use |
972 |
C<PApp::SQL::sql_exec> to store the message in a database. |
973 |
|
974 |
$ctx->fmt_cb (sub { \@_ }); |
975 |
$ctx->log_cb (sub { |
976 |
my ($msg) = @_; |
977 |
|
978 |
sql_exec "insert into log (when, subsys, prio, msg) values (?, ?, ?, ?)", |
979 |
$msg->[0] + 0, |
980 |
"$msg->[1]", |
981 |
$msg->[2] + 0, |
982 |
"$msg->[3]"; |
983 |
|
984 |
0 |
985 |
}); |
986 |
|
987 |
=item $ctx->log_to_warn |
988 |
|
989 |
Sets the C<log_cb> to simply use C<CORE::warn> to report any messages |
990 |
(usually this logs to STDERR). |
991 |
|
992 |
=item $ctx->log_to_file ($path) |
993 |
|
994 |
Sets the C<log_cb> to log to a file (by appending), unbuffered. The |
995 |
function might return before the log file has been opened or created. |
996 |
|
997 |
=item $ctx->log_to_path ($path) |
998 |
|
999 |
Same as C<< ->log_to_file >>, but opens the file for each message. This |
1000 |
is much slower, but allows you to change/move/rename/delete the file at |
1001 |
basically any time. |
1002 |
|
1003 |
Needless(?) to say, if you do not want to be bitten by some evil person |
1004 |
calling C<chdir>, the path should be absolute. Doesn't help with |
1005 |
C<chroot>, but hey... |
1006 |
|
1007 |
=item $ctx->log_to_syslog ([$facility]) |
1008 |
|
1009 |
Logs all messages via L<Sys::Syslog>, mapping C<trace> to C<debug> and |
1010 |
all the others in the obvious way. If specified, then the C<$facility> is |
1011 |
used as the facility (C<user>, C<auth>, C<local0> and so on). The default |
1012 |
facility is C<user>. |
1013 |
|
1014 |
Note that this function also sets a C<fmt_cb> - the logging part requires |
1015 |
an array reference with [$level, $str] as input. |
1016 |
|
1017 |
=cut |
1018 |
|
1019 |
sub log_cb { |
1020 |
my ($ctx, $cb) = @_; |
1021 |
|
1022 |
$ctx->[3] = $cb; |
1023 |
} |
1024 |
|
1025 |
sub fmt_cb { |
1026 |
my ($ctx, $cb) = @_; |
1027 |
|
1028 |
$ctx->[4] = $cb; |
1029 |
} |
1030 |
|
1031 |
sub log_to_warn { |
1032 |
my ($ctx, $path) = @_; |
1033 |
|
1034 |
$ctx->log_cb (sub { |
1035 |
warn shift; |
1036 |
0 |
1037 |
}); |
1038 |
} |
1039 |
|
1040 |
# this function is a good example of why threads are a must, |
1041 |
# simply for priority inversion. |
1042 |
sub _log_to_disk { |
1043 |
# eval'uating this at runtime saves 220kb rss - perl has become |
1044 |
# an insane memory waster. |
1045 |
eval q{ # poor man's autoloading {} |
1046 |
sub _log_to_disk { |
1047 |
my ($ctx, $path, $keepopen) = @_; |
1048 |
|
1049 |
my $fh; |
1050 |
my @queue; |
1051 |
my $delay; |
1052 |
my $disable; |
1053 |
|
1054 |
use AnyEvent::IO (); |
1055 |
|
1056 |
my $kick = sub { |
1057 |
undef $delay; |
1058 |
return unless @queue; |
1059 |
$delay = 1; |
1060 |
|
1061 |
# we pass $kick to $kick, so $kick itself doesn't keep a reference to $kick. |
1062 |
my $kick = shift; |
1063 |
|
1064 |
# write one or more messages |
1065 |
my $write = sub { |
1066 |
# we write as many messages as have been queued |
1067 |
my $data = join "", @queue; |
1068 |
@queue = (); |
1069 |
|
1070 |
AnyEvent::IO::aio_write $fh, $data, sub { |
1071 |
$disable = 1; |
1072 |
@_ |
1073 |
? ($_[0] == length $data or AE::log 4 => "unable to write to logfile '$path': short write") |
1074 |
: AE::log 4 => "unable to write to logfile '$path': $!"; |
1075 |
undef $disable; |
1076 |
|
1077 |
if ($keepopen) { |
1078 |
$kick->($kick); |
1079 |
} else { |
1080 |
AnyEvent::IO::aio_close ($fh, sub { |
1081 |
undef $fh; |
1082 |
$kick->($kick); |
1083 |
}); |
1084 |
} |
1085 |
}; |
1086 |
}; |
1087 |
|
1088 |
if ($fh) { |
1089 |
$write->(); |
1090 |
} else { |
1091 |
AnyEvent::IO::aio_open |
1092 |
$path, |
1093 |
AnyEvent::IO::O_CREAT | AnyEvent::IO::O_WRONLY | AnyEvent::IO::O_APPEND, |
1094 |
0666, |
1095 |
sub { |
1096 |
$fh = shift |
1097 |
or do { |
1098 |
$disable = 1; |
1099 |
AE::log 4 => "unable to open logfile '$path': $!"; |
1100 |
undef $disable; |
1101 |
return; |
1102 |
}; |
1103 |
|
1104 |
$write->(); |
1105 |
} |
1106 |
; |
1107 |
} |
1108 |
}; |
1109 |
|
1110 |
$ctx->log_cb (sub { |
1111 |
return if $disable; |
1112 |
push @queue, shift; |
1113 |
$kick->($kick) unless $delay; |
1114 |
0 |
1115 |
}); |
1116 |
|
1117 |
$kick->($kick) if $keepopen; # initial open |
1118 |
}; |
1119 |
}; |
1120 |
die if $@; |
1121 |
&_log_to_disk |
1122 |
} |
1123 |
|
1124 |
sub log_to_file { |
1125 |
my ($ctx, $path) = @_; |
1126 |
|
1127 |
_log_to_disk $ctx, $path, 1; |
1128 |
} |
1129 |
|
1130 |
sub log_to_path { |
1131 |
my ($ctx, $path) = @_; |
1132 |
|
1133 |
_log_to_disk $ctx, $path, 0; |
1134 |
} |
1135 |
|
1136 |
sub log_to_syslog { |
1137 |
my ($ctx, $facility) = @_; |
1138 |
|
1139 |
require Sys::Syslog; |
1140 |
|
1141 |
$ctx->fmt_cb (sub { |
1142 |
my $str = $_[3]; |
1143 |
$str =~ s/\n(?=.)/\n+ /g; |
1144 |
|
1145 |
[$_[2], "($_[1][0]) $str"] |
1146 |
}); |
1147 |
|
1148 |
$facility ||= "user"; |
1149 |
|
1150 |
$ctx->log_cb (sub { |
1151 |
my $lvl = $_[0][0] < 9 ? $_[0][0] : 8; |
1152 |
|
1153 |
Sys::Syslog::syslog ("$facility|" . ($lvl - 1), $_) |
1154 |
for split /\n/, $_[0][1]; |
1155 |
|
1156 |
0 |
1157 |
}); |
1158 |
} |
1159 |
|
1160 |
=back |
1161 |
|
1162 |
=head3 MESSAGE LOGGING |
1163 |
|
1164 |
These methods allow you to log messages directly to a context, without |
1165 |
going via your package context. |
1166 |
|
1167 |
=over 4 |
1168 |
|
1169 |
=item $ctx->log ($level, $msg[, @params]) |
1170 |
|
1171 |
Same as C<AnyEvent::Log::log>, but uses the given context as log context. |
1172 |
|
1173 |
Example: log a message in the context of another package. |
1174 |
|
1175 |
(AnyEvent::Log::ctx "Other::Package")->log (warn => "heely bo"); |
1176 |
|
1177 |
=item $logger = $ctx->logger ($level[, \$enabled]) |
1178 |
|
1179 |
Same as C<AnyEvent::Log::logger>, but uses the given context as log |
1180 |
context. |
1181 |
|
1182 |
=cut |
1183 |
|
1184 |
*log = \&AnyEvent::Log::_log; |
1185 |
*logger = \&AnyEvent::Log::_logger; |
1186 |
|
1187 |
=back |
1188 |
|
1189 |
=cut |
1190 |
|
1191 |
package AnyEvent::Log; |
1192 |
|
1193 |
=head1 CONFIGURATION VIA $ENV{PERL_ANYEVENT_LOG} |
1194 |
|
1195 |
Logging can also be configured by setting the environment variable |
1196 |
C<PERL_ANYEVENT_LOG> (or C<AE_LOG>). |
1197 |
|
1198 |
The value consists of one or more logging context specifications separated |
1199 |
by C<:> or whitespace. Each logging specification in turn starts with a |
1200 |
context name, followed by C<=>, followed by zero or more comma-separated |
1201 |
configuration directives, here are some examples: |
1202 |
|
1203 |
# set default logging level |
1204 |
filter=warn |
1205 |
|
1206 |
# log to file instead of to stderr |
1207 |
log=file=/tmp/mylog |
1208 |
|
1209 |
# log to file in addition to stderr |
1210 |
log=+%file:%file=file=/tmp/mylog |
1211 |
|
1212 |
# enable debug log messages, log warnings and above to syslog |
1213 |
filter=debug:log=+%warnings:%warnings=warn,syslog=LOG_LOCAL0 |
1214 |
|
1215 |
# log trace messages (only) from AnyEvent::Debug to file |
1216 |
AnyEvent::Debug=+%trace:%trace=only,trace,file=/tmp/tracelog |
1217 |
|
1218 |
A context name in the log specification can be any of the following: |
1219 |
|
1220 |
=over 4 |
1221 |
|
1222 |
=item C<collect>, C<filter>, C<log> |
1223 |
|
1224 |
Correspond to the three predefined C<$AnyEvent::Log::COLLECT>, |
1225 |
C<AnyEvent::Log::FILTER> and C<$AnyEvent::Log::LOG> contexts. |
1226 |
|
1227 |
=item C<%name> |
1228 |
|
1229 |
Context names starting with a C<%> are anonymous contexts created when the |
1230 |
name is first mentioned. The difference to package contexts is that by |
1231 |
default they have no attached slaves. |
1232 |
|
1233 |
=item a perl package name |
1234 |
|
1235 |
Any other string references the logging context associated with the given |
1236 |
Perl C<package>. In the unlikely case where you want to specify a package |
1237 |
context that matches on of the other context name forms, you can add a |
1238 |
C<::> to the package name to force interpretation as a package. |
1239 |
|
1240 |
=back |
1241 |
|
1242 |
The configuration specifications can be any number of the following: |
1243 |
|
1244 |
=over 4 |
1245 |
|
1246 |
=item C<stderr> |
1247 |
|
1248 |
Configures the context to use Perl's C<warn> function (which typically |
1249 |
logs to C<STDERR>). Works like C<log_to_warn>. |
1250 |
|
1251 |
=item C<file=>I<path> |
1252 |
|
1253 |
Configures the context to log to a file with the given path. Works like |
1254 |
C<log_to_file>. |
1255 |
|
1256 |
=item C<path=>I<path> |
1257 |
|
1258 |
Configures the context to log to a file with the given path. Works like |
1259 |
C<log_to_path>. |
1260 |
|
1261 |
=item C<syslog> or C<syslog=>I<expr> |
1262 |
|
1263 |
Configures the context to log to syslog. If I<expr> is given, then it is |
1264 |
evaluated in the L<Sys::Syslog> package, so you could use: |
1265 |
|
1266 |
log=syslog=LOG_LOCAL0 |
1267 |
|
1268 |
=item C<nolog> |
1269 |
|
1270 |
Configures the context to not log anything by itself, which is the |
1271 |
default. Same as C<< $ctx->log_cb (undef) >>. |
1272 |
|
1273 |
=item C<cap=>I<level> |
1274 |
|
1275 |
Caps logging messages entering this context at the given level, i.e. |
1276 |
reduces the priority of messages with higher priority than this level. The |
1277 |
default is C<0> (or C<off>), meaning the priority will not be touched. |
1278 |
|
1279 |
=item C<0> or C<off> |
1280 |
|
1281 |
Sets the logging level of the context to C<0>, i.e. all messages will be |
1282 |
filtered out. |
1283 |
|
1284 |
=item C<all> |
1285 |
|
1286 |
Enables all logging levels, i.e. filtering will effectively be switched |
1287 |
off (the default). |
1288 |
|
1289 |
=item C<only> |
1290 |
|
1291 |
Disables all logging levels, and changes the interpretation of following |
1292 |
level specifications to enable the specified level only. |
1293 |
|
1294 |
Example: only enable debug messages for a context. |
1295 |
|
1296 |
context=only,debug |
1297 |
|
1298 |
=item C<except> |
1299 |
|
1300 |
Enables all logging levels, and changes the interpretation of following |
1301 |
level specifications to disable that level. Rarely used. |
1302 |
|
1303 |
Example: enable all logging levels except fatal and trace (this is rather |
1304 |
nonsensical). |
1305 |
|
1306 |
filter=exept,fatal,trace |
1307 |
|
1308 |
=item C<level> |
1309 |
|
1310 |
Enables all logging levels, and changes the interpretation of following |
1311 |
level specifications to be "that level or any higher priority |
1312 |
message". This is the default. |
1313 |
|
1314 |
Example: log anything at or above warn level. |
1315 |
|
1316 |
filter=warn |
1317 |
|
1318 |
# or, more verbose |
1319 |
filter=only,level,warn |
1320 |
|
1321 |
=item C<1>..C<9> or a logging level name (C<error>, C<debug> etc.) |
1322 |
|
1323 |
A numeric loglevel or the name of a loglevel will be interpreted according |
1324 |
to the most recent C<only>, C<except> or C<level> directive. By default, |
1325 |
specifying a logging level enables that and any higher priority messages. |
1326 |
|
1327 |
=item C<+>I<context> |
1328 |
|
1329 |
Attaches the named context as slave to the context. |
1330 |
|
1331 |
=item C<+> |
1332 |
|
1333 |
A lone C<+> detaches all contexts, i.e. clears the slave list from the |
1334 |
context. Anonymous (C<%name>) contexts have no attached slaves by default, |
1335 |
but package contexts have the parent context as slave by default. |
1336 |
|
1337 |
Example: log messages from My::Module to a file, do not send them to the |
1338 |
default log collector. |
1339 |
|
1340 |
My::Module=+,file=/tmp/mymodulelog |
1341 |
|
1342 |
=back |
1343 |
|
1344 |
Any character can be escaped by prefixing it with a C<\> (backslash), as |
1345 |
usual, so to log to a file containing a comma, colon, backslash and some |
1346 |
spaces in the filename, you would do this: |
1347 |
|
1348 |
PERL_ANYEVENT_LOG='log=file=/some\ \:file\ with\,\ \\-escapes' |
1349 |
|
1350 |
Since whitespace (which includes newlines) is allowed, it is fine to |
1351 |
specify multiple lines in C<PERL_ANYEVENT_LOG>, e.g.: |
1352 |
|
1353 |
PERL_ANYEVENT_LOG=" |
1354 |
filter=warn |
1355 |
AnyEvent::Debug=+%trace |
1356 |
%trace=only,trace,+log |
1357 |
" myprog |
1358 |
|
1359 |
Also, in the unlikely case when you want to concatenate specifications, |
1360 |
use whitespace as separator, as C<::> will be interpreted as part of a |
1361 |
module name, an empty spec with two separators: |
1362 |
|
1363 |
PERL_ANYEVENT_LOG="$PERL_ANYEVENT_LOG MyMod=debug" |
1364 |
|
1365 |
=cut |
1366 |
|
1367 |
for (my $spec = $ENV{PERL_ANYEVENT_LOG}) { |
1368 |
my %anon; |
1369 |
|
1370 |
my $pkg = sub { |
1371 |
$_[0] eq "log" ? $LOG |
1372 |
: $_[0] eq "filter" ? $FILTER |
1373 |
: $_[0] eq "collect" ? $COLLECT |
1374 |
: $_[0] =~ /^%(.+)$/ ? ($anon{$1} ||= do { my $ctx = ctx undef; $ctx->[0] = $_[0]; $ctx }) |
1375 |
: $_[0] =~ /^(.*?)(?:::)?$/ ? ctx "$1" # egad :/ |
1376 |
: die # never reached? |
1377 |
}; |
1378 |
|
1379 |
/\G[[:space:]]+/gc; # skip initial whitespace |
1380 |
|
1381 |
while (/\G((?:[^:=[:space:]]+|::|\\.)+)=/gc) { |
1382 |
my $ctx = $pkg->($1); |
1383 |
my $level = "level"; |
1384 |
|
1385 |
while (/\G((?:[^,:[:space:]]+|::|\\.)+)/gc) { |
1386 |
for ("$1") { |
1387 |
if ($_ eq "stderr" ) { $ctx->log_to_warn; |
1388 |
} elsif (/^file=(.+)/ ) { $ctx->log_to_file ("$1"); |
1389 |
} elsif (/^path=(.+)/ ) { $ctx->log_to_path ("$1"); |
1390 |
} elsif (/^syslog(?:=(.*))?/ ) { require Sys::Syslog; $ctx->log_to_syslog ("$1"); |
1391 |
} elsif ($_ eq "nolog" ) { $ctx->log_cb (undef); |
1392 |
} elsif (/^cap=(.+)/ ) { $ctx->cap ("$1"); |
1393 |
} elsif (/^\+(.+)$/ ) { $ctx->attach ($pkg->("$1")); |
1394 |
} elsif ($_ eq "+" ) { $ctx->slaves; |
1395 |
} elsif ($_ eq "off" or $_ eq "0") { $ctx->level (0); |
1396 |
} elsif ($_ eq "all" ) { $ctx->level ("all"); |
1397 |
} elsif ($_ eq "level" ) { $ctx->level ("all"); $level = "level"; |
1398 |
} elsif ($_ eq "only" ) { $ctx->level ("off"); $level = "enable"; |
1399 |
} elsif ($_ eq "except" ) { $ctx->level ("all"); $level = "disable"; |
1400 |
} elsif (/^\d$/ ) { $ctx->$level ($_); |
1401 |
} elsif (exists $STR2LEVEL{$_} ) { $ctx->$level ($_); |
1402 |
} else { die "PERL_ANYEVENT_LOG ($spec): parse error at '$_'\n"; |
1403 |
} |
1404 |
} |
1405 |
|
1406 |
/\G,/gc or last; |
1407 |
} |
1408 |
|
1409 |
/\G[:[:space:]]+/gc or last; |
1410 |
} |
1411 |
|
1412 |
/\G[[:space:]]+/gc; # skip trailing whitespace |
1413 |
|
1414 |
if (/\G(.+)/g) { |
1415 |
die "PERL_ANYEVENT_LOG ($spec): parse error at '$1'\n"; |
1416 |
} |
1417 |
} |
1418 |
|
1419 |
=head1 EXAMPLES |
1420 |
|
1421 |
This section shows some common configurations, both as code, and as |
1422 |
C<PERL_ANYEVENT_LOG> string. |
1423 |
|
1424 |
=over 4 |
1425 |
|
1426 |
=item Setting the global logging level. |
1427 |
|
1428 |
Either put C<PERL_ANYEVENT_VERBOSE=><number> into your environment before |
1429 |
running your program, use C<PERL_ANYEVENT_LOG> or modify the log level of |
1430 |
the root context at runtime: |
1431 |
|
1432 |
PERL_ANYEVENT_VERBOSE=5 ./myprog |
1433 |
|
1434 |
PERL_ANYEVENT_LOG=log=warn |
1435 |
|
1436 |
$AnyEvent::Log::FILTER->level ("warn"); |
1437 |
|
1438 |
=item Append all messages to a file instead of sending them to STDERR. |
1439 |
|
1440 |
This is affected by the global logging level. |
1441 |
|
1442 |
$AnyEvent::Log::LOG->log_to_file ($path); |
1443 |
|
1444 |
PERL_ANYEVENT_LOG=log=file=/some/path |
1445 |
|
1446 |
=item Write all messages with priority C<error> and higher to a file. |
1447 |
|
1448 |
This writes them only when the global logging level allows it, because |
1449 |
it is attached to the default context which is invoked I<after> global |
1450 |
filtering. |
1451 |
|
1452 |
$AnyEvent::Log::FILTER->attach ( |
1453 |
new AnyEvent::Log::Ctx log_to_file => $path); |
1454 |
|
1455 |
PERL_ANYEVENT_LOG=filter=+%filelogger:%filelogger=file=/some/path |
1456 |
|
1457 |
This writes them regardless of the global logging level, because it is |
1458 |
attached to the toplevel context, which receives all messages I<before> |
1459 |
the global filtering. |
1460 |
|
1461 |
$AnyEvent::Log::COLLECT->attach ( |
1462 |
new AnyEvent::Log::Ctx log_to_file => $path); |
1463 |
|
1464 |
PERL_ANYEVENT_LOG=%filelogger=file=/some/path:collect=+%filelogger |
1465 |
|
1466 |
In both cases, messages are still written to STDERR. |
1467 |
|
1468 |
=item Additionally log all messages with C<warn> and higher priority to |
1469 |
C<syslog>, but cap at C<error>. |
1470 |
|
1471 |
This logs all messages to the default log target, but also logs messages |
1472 |
with priority C<warn> or higher (and not filtered otherwise) to syslog |
1473 |
facility C<user>. Messages with priority higher than C<error> will be |
1474 |
logged with level C<error>. |
1475 |
|
1476 |
$AnyEvent::Log::LOG->attach ( |
1477 |
new AnyEvent::Log::Ctx |
1478 |
level => "warn", |
1479 |
cap => "error", |
1480 |
syslog => "user", |
1481 |
); |
1482 |
|
1483 |
PERL_ANYEVENT_LOG=log=+%syslog:%syslog=warn,cap=error,syslog |
1484 |
|
1485 |
=item Write trace messages (only) from L<AnyEvent::Debug> to the default logging target(s). |
1486 |
|
1487 |
Attach the C<$AnyEvent::Log::LOG> context to the C<AnyEvent::Debug> |
1488 |
context - this simply circumvents the global filtering for trace messages. |
1489 |
|
1490 |
my $debug = AnyEvent::Debug->AnyEvent::Log::ctx; |
1491 |
$debug->attach ($AnyEvent::Log::LOG); |
1492 |
|
1493 |
PERL_ANYEVENT_LOG=AnyEvent::Debug=+log |
1494 |
|
1495 |
This of course works for any package, not just L<AnyEvent::Debug>, but |
1496 |
assumes the log level for AnyEvent::Debug hasn't been changed from the |
1497 |
default. |
1498 |
|
1499 |
=back |
1500 |
|
1501 |
=head1 ASYNCHRONOUS DISK I/O |
1502 |
|
1503 |
This module uses L<AnyEvent::IO> to actually write log messages (in |
1504 |
C<log_to_file> and C<log_to_path>), so it doesn't block your program when |
1505 |
the disk is busy and a non-blocking L<AnyEvent::IO> backend is available. |
1506 |
|
1507 |
=head1 AUTHOR |
1508 |
|
1509 |
Marc Lehmann <schmorp@schmorp.de> |
1510 |
http://anyevent.schmorp.de |
1511 |
|
1512 |
=cut |
1513 |
|
1514 |
1 |
1515 |
|