ViewVC Help
View File | Revision Log | Show Annotations | Download File
/cvs/AnyEvent/lib/AnyEvent/Log.pm
(Generate patch)

Comparing AnyEvent/lib/AnyEvent/Log.pm (file contents):
Revision 1.2 by root, Tue Aug 16 14:47:27 2011 UTC vs.
Revision 1.10 by root, Fri Aug 19 21:17:08 2011 UTC

2 2
3AnyEvent::Log - simple logging "framework" 3AnyEvent::Log - simple logging "framework"
4 4
5=head1 SYNOPSIS 5=head1 SYNOPSIS
6 6
7 # simple use
8 use AnyEvent;
9
10 AE::log debug => "hit my knee";
11 AE::log warn => "it's a bit too hot";
12 AE::log error => "the flag was false!";
13 AE::log fatal => "the bit toggled! run!";
14
15 # "complex" use
7 use AnyEvent::Log; 16 use AnyEvent::Log;
17
18 my $tracer = AnyEvent::Log::logger trace => \$my $trace;
19
20 $tracer->("i am here") if $trace;
21 $tracer->(sub { "lots of data: " . Dumper $self }) if $trace;
22
23 # configuration
24
25 # set logging for this package to maximum
26 AnyEvent::Log::ctx->level ("all");
27
28 # set logging globally to anything below debug
29 (AnyEvent::Log::ctx "")->level ("notice");
30
31 # see also EXAMPLES, below
32
33 # disable logging for package "AnyEvent" and all packages below it
34 AnyEvent->AnyEvent::Log::ctx->level (0);
35
36 # log everything below debug to a file, for the whole program
37 my $ctx = AnyEvent::Log::ctx;
38 $ctx->log_cb (sub { print FILE shift; 0 });
39 (AnyEvent::Log::ctx "")->add ($ctx);
8 40
9=head1 DESCRIPTION 41=head1 DESCRIPTION
10 42
11This module implements a relatively simple "logging framework". It doesn't 43This module implements a relatively simple "logging framework". It doesn't
12attempt to be "the" logging solution or even "a" logging solution for 44attempt to be "the" logging solution or even "a" logging solution for
13AnyEvent - AnyEvent simply creates logging messages internally, and this 45AnyEvent - AnyEvent simply creates logging messages internally, and this
14module more or less exposes the mechanism, with some extra spiff to allow 46module more or less exposes the mechanism, with some extra spiff to allow
15using it from other modules as well. 47using it from other modules as well.
16 48
17Remember that the default verbosity level is C<0>, so nothing 49Remember that the default verbosity level is C<0>, so nothing will be
18will be logged, ever, unless you set C<$Anyvent::VERBOSE> or 50logged, ever, unless you set C<PERL_ANYEVENT_VERBOSE> to a higher number
19C<PERL_ANYEVENT_VERBOSE> to a higher number. 51before starting your program, or change the logging level at runtime wiht
52something like:
20 53
21Possible future extensions are to allow custom log targets (where the 54 use AnyEvent;
22level is an object), log filtering based on package, formatting, aliasing 55 (AnyEvent::Log::ctx "")->level ("info");
23or package groups.
24 56
57The design goal behind this module was to keep it simple (and small),
58but make it powerful enough to be potentially useful for any module, and
59extensive enough for the most common tasks, such as logging to multiple
60targets, or being able to log into a database.
61
25=head1 LOG FUNCTIONS 62=head1 LOGGING FUNCTIONS
26 63
27These functions allow you to log messages. They always use the caller's 64These functions allow you to log messages. They always use the caller's
28package as a "logging module/source". Also, The main logging function is 65package as a "logging module/source". Also, the main logging function is
29easily available as C<AnyEvent::log> or C<AE::log> when the C<AnyEvent> 66callable as C<AnyEvent::log> or C<AE::log> when the C<AnyEvent> module is
30module is loaded. 67loaded.
31 68
32=over 4 69=over 4
33 70
34=cut 71=cut
35 72
37 74
38use Carp (); 75use Carp ();
39use POSIX (); 76use POSIX ();
40 77
41use AnyEvent (); BEGIN { AnyEvent::common_sense } 78use AnyEvent (); BEGIN { AnyEvent::common_sense }
79use AnyEvent::Util ();
42 80
43our ($now_int, $now_str1, $now_str2); 81our ($now_int, $now_str1, $now_str2);
44 82
45# Format Time, not public - yet? 83# Format Time, not public - yet?
46sub ft($) { 84sub ft($) {
51 if $now_int != $i; 89 if $now_int != $i;
52 90
53 "$now_str1$f$now_str2" 91 "$now_str1$f$now_str2"
54} 92}
55 93
94our %CTX; # all logging contexts
95
96# creates a default package context object for the given package
97sub _pkg_ctx($) {
98 my $ctx = bless [$_[0], (1 << 10) - 1 - 1, {}], "AnyEvent::Log::Ctx";
99
100 # link "parent" package
101 my $pkg = $_[0] =~ /^(.+)::/ ? $1 : "";
102
103 $pkg = $CTX{$pkg} ||= &_pkg_ctx ($pkg);
104 $ctx->[2]{$pkg+0} = $pkg;
105
106 $ctx
107}
108
56=item AnyEvent::Log::log $level, $msg[, @args] 109=item AnyEvent::Log::log $level, $msg[, @args]
57 110
58Requests logging of the given C<$msg> with the given log level (1..9). 111Requests logging of the given C<$msg> with the given log level (1..9).
59You can also use the following strings as log level: C<fatal> (1), 112You can also use the following strings as log level: C<fatal> (1),
60C<alert> (2), C<critical> (3), C<error> (4), C<warn> (5), C<note> (6), 113C<alert> (2), C<critical> (3), C<error> (4), C<warn> (5), C<note> (6),
66C<$msg> is interpreted as an sprintf format string. 119C<$msg> is interpreted as an sprintf format string.
67 120
68The C<$msg> should not end with C<\n>, but may if that is convenient for 121The C<$msg> should not end with C<\n>, but may if that is convenient for
69you. Also, multiline messages are handled properly. 122you. Also, multiline messages are handled properly.
70 123
71In addition, for possible future expansion, C<$msg> must not start with an 124Last not least, C<$msg> might be a code reference, in which case it is
72angle bracket (C<< < >>). 125supposed to return the message. It will be called only then the message
126actually gets logged, which is useful if it is costly to create the
127message in the first place.
73 128
74Whether the given message will be logged depends on the maximum log level 129Whether the given message will be logged depends on the maximum log level
75and the caller's package. 130and the caller's package.
76 131
77Note that you can (and should) call this function as C<AnyEvent::log> or 132Note that you can (and should) call this function as C<AnyEvent::log> or
78C<AE::log>, without C<use>-ing this module if possible, as those functions 133C<AE::log>, without C<use>-ing this module if possible (i.e. you don't
79will laod the logging module on demand only. 134need any additional functionality), as those functions will load the
135logging module on demand only. They are also much shorter to write.
136
137Also, if you otpionally generate a lot of debug messages (such as when
138tracing some code), you should look into using a logger callback and a
139boolean enabler (see C<logger>, below).
140
141Example: log something at error level.
142
143 AE::log error => "something";
144
145Example: use printf-formatting.
146
147 AE::log info => "%5d %-10.10s %s", $index, $category, $msg;
148
149Example: only generate a costly dump when the message is actually being logged.
150
151 AE::log debug => sub { require Data::Dump; Data::Dump::dump \%cache };
80 152
81=cut 153=cut
82 154
83# also allow syslog equivalent names 155# also allow syslog equivalent names
84our %STR2LEVEL = ( 156our %STR2LEVEL = (
91 info => 7, 163 info => 7,
92 debug => 8, 164 debug => 8,
93 trace => 9, 165 trace => 9,
94); 166);
95 167
168sub now () { time }
169
170AnyEvent::post_detect {
171 *now = \&AE::now;
172};
173
96our @LEVEL2STR = qw(0 fatal alert crit error warn note info debug trace); 174our @LEVEL2STR = qw(0 fatal alert crit error warn note info debug trace);
97 175
98sub log($$;@) { 176# time, ctx, level, msg
99 my ($targ, $msg, @args) = @_; 177sub _format($$$$) {
178 my $pfx = ft $_[0];
179 my @res;
100 180
101 my $level = ref $targ ? die "Can't use reference as logging level (yet)" 181 for (split /\n/, sprintf "%-5s %s: %s", $LEVEL2STR[$_[2]], $_[1][0], $_[3]) {
102 : $targ > 0 && $targ <= 9 ? $targ+0 182 push @res, "$pfx $_\n";
103 : $STR2LEVEL{$targ} || Carp::croak "$targ: not a valid logging level, caught";
104
105 return if $level > $AnyEvent::VERBOSE;
106
107 my $pkg = (caller)[0];
108
109 $msg = sprintf $msg, @args if @args;
110 $msg =~ s/\n$//;
111
112 # now we have a message, log it
113 #TODO: could do LOTS of stuff here, and should, at least in some later version
114
115 $msg = sprintf "%5s (%s) %s", $LEVEL2STR[$level], $pkg, $msg;
116 my $pfx = ft AE::now;
117
118 for (split /\n/, $msg) {
119 printf STDERR "$pfx $_\n";
120 $pfx = "\t"; 183 $pfx = "\t";
121 } 184 }
122 185
186 join "", @res
187}
188
189sub _log {
190 my ($ctx, $level, $format, @args) = @_;
191
192 $level = $level > 0 && $level <= 9 ? $level+0 : $STR2LEVEL{$level} || Carp::croak "$level: not a valid logging level, caught";
193
194 my $mask = 1 << $level;
195
196 my (@ctx, $now, $fmt);
197
198 do {
199 # skip if masked
200 next unless $ctx->[1] & $mask;
201
202 if ($ctx->[3]) {
203 # logging target found
204
205 # now get raw message, unless we have it already
206 unless ($now) {
207 $format = $format->() if ref $format;
208 $format = sprintf $format, @args if @args;
209 $format =~ s/\n$//;
210 $now = AE::now;
211 };
212
213 # format msg
214 my $str = $ctx->[4]
215 ? $ctx->[4]($now, $_[0], $level, $format)
216 : $fmt ||= _format $now, $_[0], $level, $format;
217
218 $ctx->[3]($str)
219 and next;
220 }
221
222 # not masked, not consume - propagate to parent contexts
223 push @ctx, values %{ $ctx->[2] };
224 } while $ctx = pop @ctx;
225
123 exit 1 if $level <= 1; 226 exit 1 if $level <= 1;
124} 227}
125 228
229sub log($$;@) {
230 _log
231 $CTX{ (caller)[0] } ||= _pkg_ctx +(caller)[0],
232 @_;
233}
234
126*AnyEvent::log = *AE::log = \&log; 235*AnyEvent::log = *AE::log = \&log;
127 236
128#TODO 237=item $logger = AnyEvent::Log::logger $level[, \$enabled]
238
239Creates a code reference that, when called, acts as if the
240C<AnyEvent::Log::log> function was called at this point with the givne
241level. C<$logger> is passed a C<$msg> and optional C<@args>, just as with
242the C<AnyEvent::Log::log> function:
243
244 my $debug_log = AnyEvent::Log::logger "debug";
245
246 $debug_log->("debug here");
247 $debug_log->("%06d emails processed", 12345);
248 $debug_log->(sub { $obj->as_string });
249
250The idea behind this function is to decide whether to log before actually
251logging - when the C<logger> function is called once, but the returned
252logger callback often, then this can be a tremendous speed win.
253
254Despite this speed advantage, changes in logging configuration will
255still be reflected by the logger callback, even if configuration changes
256I<after> it was created.
257
258To further speed up logging, you can bind a scalar variable to the logger,
259which contains true if the logger should be called or not - if it is
260false, calling the logger can be safely skipped. This variable will be
261updated as long as C<$logger> is alive.
262
263Full example:
264
265 # near the init section
266 use AnyEvent::Log;
267
268 my $debug_log = AnyEvent:Log::logger debug => \my $debug;
269
270 # and later in your program
271 $debug_log->("yo, stuff here") if $debug;
272
273 $debug and $debug_log->("123");
274
275Note: currently the enabled var is always true - that will be fixed in a
276future version :)
277
278=cut
279
280our %LOGGER;
281
282# re-assess logging status for all loggers
283sub _reassess {
284 for (@_ ? $LOGGER{$_[0]} : values %LOGGER) {
285 my ($ctx, $level, $renabled) = @$_;
286
287 # to detetc whether a message would be logged, we # actually
288 # try to log one and die. this isn't # fast, but we can be
289 # sure that the logging decision is correct :)
290
291 $$renabled = !eval {
292 local $SIG{__DIE__};
293
294 _log $ctx, $level, sub { die };
295
296 1
297 };
298
299 $$renabled = 1; # TODO
300 }
301}
302
303sub _logger($;$) {
304 my ($ctx, $level, $renabled) = @_;
305
306 $renabled ||= \my $enabled;
307
308 $$renabled = 1;
309
310 my $logger = [$ctx, $level, $renabled];
311
312 $LOGGER{$logger+0} = $logger;
313
314 _reassess $logger+0;
315
316 my $guard = AnyEvent::Util::guard {
317 # "clean up"
318 delete $LOGGER{$logger+0};
319 };
320
321 sub {
322 $guard if 0; # keep guard alive, but don't cause runtime overhead
323
324 _log $ctx, $level, @_
325 if $$renabled;
326 }
327}
328
329sub logger($;$) {
330 _logger
331 $CTX{ (caller)[0] } ||= _pkg_ctx +(caller)[0],
332 @_
333}
129 334
130=back 335=back
131 336
132=head1 CONFIGURATION FUNCTIONALITY 337=head1 LOGGING CONTEXTS
133 338
134None, yet, except for C<PERL_ANYEVENT_VERBOSE>, described in the L<AnyEvent> manpage. 339This module associates every log message with a so-called I<logging
340context>, based on the package of the caller. Every perl package has its
341own logging context.
342
343A logging context has three major responsibilities: filtering, logging and
344propagating the message.
345
346For the first purpose, filtering, each context has a set of logging
347levels, called the log level mask. Messages not in the set will be ignored
348by this context (masked).
349
350For logging, the context stores a formatting callback (which takes the
351timestamp, context, level and string message and formats it in the way
352it should be logged) and a logging callback (which is responsible for
353actually logging the formatted message and telling C<AnyEvent::Log>
354whether it has consumed the message, or whether it should be propagated).
355
356For propagation, a context can have any number of attached I<parent
357contexts>. Any message that is neither masked by the logging mask nor
358masked by the logging callback returning true will be passed to all parent
359contexts.
360
361=head2 DEFAULTS
362
363By default, all logging contexts have an full set of log levels ("all"), a
364disabled logging callback and the default formatting callback.
365
366Package contexts have the package name as logging title by default.
367
368They have exactly one parent - the context of the "parent" package. The
369parent package is simply defined to be the package name without the last
370component, i.e. C<AnyEvent::Debug::Wrapped> becomes C<AnyEvent::Debug>,
371and C<AnyEvent> becomes the empty string.
372
373Since perl packages form only an approximate hierarchy, this parent
374context can of course be removed.
375
376All other (anonymous) contexts have no parents and an empty title by
377default.
378
379When the module is first loaded, it configures the root context (the one
380with the empty string) to simply dump all log messages to C<STDERR>,
381and sets it's log level set to all levels up to the one specified by
382C<$ENV{PERL_ANYEVENT_VERBOSE}>.
383
384The effect of all this is that log messages, by default, wander up to the
385root context and will be logged to STDERR if their log level is less than
386or equal to C<$ENV{PERL_ANYEVENT_VERBOSE}>.
387
388=head2 CREATING/FINDING A CONTEXT
135 389
136=over 4 390=over 4
137 391
392=item $ctx = AnyEvent::Log::ctx [$pkg]
393
394This function creates or returns a logging context (which is an object).
395
396If a package name is given, then the context for that packlage is
397returned. If it is called without any arguments, then the context for the
398callers package is returned (i.e. the same context as a C<AE::log> call
399would use).
400
401If C<undef> is given, then it creates a new anonymous context that is not
402tied to any package and is destroyed when no longer referenced.
403
138=cut 404=cut
405
406sub ctx(;$) {
407 my $pkg = @_ ? shift : (caller)[0];
408
409 ref $pkg
410 ? $pkg
411 : defined $pkg
412 ? $CTX{$pkg} ||= AnyEvent::Log::_pkg_ctx $pkg
413 : bless [undef, (1 << 10) - 1 - 1], "AnyEvent::Log::Ctx"
414}
415
416# create default root context
417{
418 my $root = ctx undef;
419 $root->[0] = "";
420 $root->title ("default");
421 $root->level ($AnyEvent::VERBOSE); undef $AnyEvent::VERBOSE;
422 $root->log_cb (sub {
423 print STDERR shift;
424 0
425 });
426 $CTX{""} = $root;
427}
428
429=back
430
431=cut
432
433package AnyEvent::Log::Ctx;
434
435# 0 1 2 3 4
436# [$title, $level, %$parents, &$logcb, &$fmtcb]
437
438=head2 CONFIGURING A LOG CONTEXT
439
440The following methods can be used to configure the logging context.
441
442=over 4
443
444=item $ctx->title ([$new_title])
445
446Returns the title of the logging context - this is the package name, for
447package contexts, and a user defined string for all others.
448
449If C<$new_title> is given, then it replaces the package name or title.
450
451=cut
452
453sub title {
454 $_[0][0] = $_[1] if @_ > 1;
455 $_[0][0]
456}
457
458=back
459
460=head3 LOGGING LEVELS
461
462The following methods deal with the logging level set associated with the
463log context.
464
465The most common method to use is probably C<< $ctx->level ($level) >>,
466which configures the specified and any higher priority levels.
467
468All functions which accept a list of levels also accept the special string
469C<all> which expands to all logging levels.
470
471=over 4
472
473=item $ctx->levels ($level[, $level...)
474
475Enables logging for the given levels and disables it for all others.
476
477=item $ctx->level ($level)
478
479Enables logging for the given level and all lower level (higher priority)
480ones. In addition to normal logging levels, specifying a level of C<0> or
481C<off> disables all logging for this level.
482
483Example: log warnings, errors and higher priority messages.
484
485 $ctx->level ("warn");
486 $ctx->level (5); # same thing, just numeric
487
488=item $ctx->enable ($level[, $level...])
489
490Enables logging for the given levels, leaving all others unchanged.
491
492=item $ctx->disable ($level[, $level...])
493
494Disables logging for the given levels, leaving all others unchanged.
495
496=cut
497
498sub _lvl_lst {
499 map {
500 $_ > 0 && $_ <= 9 ? $_+0
501 : $_ eq "all" ? (1 .. 9)
502 : $STR2LEVEL{$_} || Carp::croak "$_: not a valid logging level, caught"
503 } @_
504}
505
506our $NOP_CB = sub { 0 };
507
508sub levels {
509 my $ctx = shift;
510 $ctx->[1] = 0;
511 $ctx->[1] |= 1 << $_
512 for &_lvl_lst;
513 AnyEvent::Log::_reassess;
514}
515
516sub level {
517 my $ctx = shift;
518 my $lvl = $_[0] =~ /^(?:0|off|none)$/ ? 0 : (_lvl_lst $_[0])[-1];
519
520 $ctx->[1] = ((1 << $lvl) - 1) << 1;
521 AnyEvent::Log::_reassess;
522}
523
524sub enable {
525 my $ctx = shift;
526 $ctx->[1] |= 1 << $_
527 for &_lvl_lst;
528 AnyEvent::Log::_reassess;
529}
530
531sub disable {
532 my $ctx = shift;
533 $ctx->[1] &= ~(1 << $_)
534 for &_lvl_lst;
535 AnyEvent::Log::_reassess;
536}
537
538=back
539
540=head3 PARENT CONTEXTS
541
542The following methods attach and detach another logging context to a
543logging context.
544
545Log messages are propagated to all parent contexts, unless the logging
546callback consumes the message.
547
548=over 4
549
550=item $ctx->attach ($ctx2[, $ctx3...])
551
552Attaches the given contexts as parents to this context. It is not an error
553to add a context twice (the second add will be ignored).
554
555A context can be specified either as package name or as a context object.
556
557=item $ctx->detach ($ctx2[, $ctx3...])
558
559Removes the given parents from this context - it's not an error to attempt
560to remove a context that hasn't been added.
561
562A context can be specified either as package name or as a context object.
563
564=cut
565
566sub attach {
567 my $ctx = shift;
568
569 $ctx->[2]{$_+0} = $_
570 for map { AnyEvent::Log::ctx $_ } @_;
571}
572
573sub detach {
574 my $ctx = shift;
575
576 delete $ctx->[2]{$_+0}
577 for map { AnyEvent::Log::ctx $_ } @_;
578}
579
580=back
581
582=head3 MESSAGE LOGGING
583
584The following methods configure how the logging context actually does
585the logging (which consists of formatting the message and printing it or
586whatever it wants to do with it) and also allows you to log messages
587directly to a context, without going via your package context.
588
589=over 4
590
591=item $ctx->log_cb ($cb->($str))
592
593Replaces the logging callback on the context (C<undef> disables the
594logging callback).
595
596The logging callback is responsible for handling formatted log messages
597(see C<fmt_cb> below) - normally simple text strings that end with a
598newline (and are possibly multiline themselves).
599
600It also has to return true iff it has consumed the log message, and false
601if it hasn't. Consuming a message means that it will not be sent to any
602parent context. When in doubt, return C<0> from your logging callback.
603
604Example: a very simple logging callback, simply dump the message to STDOUT
605and do not consume it.
606
607 $ctx->log_cb (sub { print STDERR shift; 0 });
608
609You can filter messages by having a log callback that simply returns C<1>
610and does not do anything with the message, but this counts as "message
611being logged" and might not be very efficient.
612
613Example: propagate all messages except for log levels "debug" and
614"trace". The messages will still be generated, though, which can slow down
615your program.
616
617 $ctx->levels ("debug", "trace");
618 $ctx->log_cb (sub { 1 }); # do not log, but eat debug and trace messages
619
620=item $ctx->fmt_cb ($fmt_cb->($timestamp, $ctx, $level, $message))
621
622Replaces the formatting callback on the context (C<undef> restores the
623default formatter).
624
625The callback is passed the (possibly fractional) timestamp, the original
626logging context, the (numeric) logging level and the raw message string and needs to
627return a formatted log message. In most cases this will be a string, but
628it could just as well be an array reference that just stores the values.
629
630Example: format just the raw message, with numeric log level in angle
631brackets.
632
633 $ctx->fmt_cb (sub {
634 my ($time, $ctx, $lvl, $msg) = @_;
635
636 "<$lvl>$msg\n"
637 });
638
639Example: return an array reference with just the log values, and use
640C<PApp::SQL::sql_exec> to store the emssage in a database.
641
642 $ctx->fmt_cb (sub { \@_ });
643 $ctx->log_cb (sub {
644 my ($msg) = @_;
645
646 sql_exec "insert into log (when, subsys, prio, msg) values (?, ?, ?, ?)",
647 $msg->[0] + 0,
648 "$msg->[1]",
649 $msg->[2] + 0,
650 "$msg->[3]";
651
652 0
653 });
654
655=cut
656
657sub log_cb {
658 my ($ctx, $cb) = @_;
659
660 $ctx->[3] = $cb;
661}
662
663sub fmt_cb {
664 my ($ctx, $cb) = @_;
665
666 $ctx->[4] = $cb;
667}
668
669=item $ctx->log ($level, $msg[, @params])
670
671Same as C<AnyEvent::Log::log>, but uses the given context as log context.
672
673=item $logger = $ctx->logger ($level[, \$enabled])
674
675Same as C<AnyEvent::Log::logger>, but uses the given context as log
676context.
677
678=cut
679
680*log = \&AnyEvent::Log::_log;
681*logger = \&AnyEvent::Log::_logger;
139 682
1401; 6831;
141 684
142=back 685=back
143 686

Diff Legend

Removed lines
+ Added lines
< Changed lines
> Changed lines