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

Diff Legend

Removed lines
+ Added lines
< Changed lines
> Changed lines