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.32 by root, Thu Aug 25 04:56:16 2011 UTC vs.
Revision 1.44 by root, Mon Sep 26 11:32:19 2011 UTC

… …
6 6
7Simple uses: 7Simple uses:
8 8
9 use AnyEvent; 9 use AnyEvent;
10 10
11 AE::log debug => "hit my knee"; 11 AE::log trace => "going to call function abc";
12 AE::log warn => "it's a bit too hot"; 12 AE::log debug => "the function returned 3";
13 AE::log error => "the flag was false!"; 13 AE::log info => "file soandso successfully deleted";
14 AE::log fatal => "the bit toggled! run!"; # never returns 14 AE::log note => "wanted to create config, but config was alraedy created";
15 AE::log warn => "couldn't delete the file";
16 AE::log error => "failed to retrieve data";
17 AE::log crit => "the battery temperature is too hot";
18 AE::log alert => "the battery died";
19 AE::log fatal => "no config found, cannot continue"; # never returns
15 20
21Log 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
16"Complex" uses (for speed sensitive code): 34"Complex" uses (for speed sensitive code, e.g. trace/debug messages):
17 35
18 use AnyEvent::Log; 36 use AnyEvent::Log;
19 37
20 my $tracer = AnyEvent::Log::logger trace => \$my $trace; 38 my $tracer = AnyEvent::Log::logger trace => \$my $trace;
21 39
… …
32 50
33 # send all critical and higher priority messages to syslog, 51 # send all critical and higher priority messages to syslog,
34 # regardless of (most) other settings 52 # regardless of (most) other settings
35 $AnyEvent::Log::COLLECT->attach (new AnyEvent::Log::Ctx 53 $AnyEvent::Log::COLLECT->attach (new AnyEvent::Log::Ctx
36 level => "critical", 54 level => "critical",
37 log_to_syslog => 0, 55 log_to_syslog => "user",
38 ); 56 );
39 57
40=head1 DESCRIPTION 58=head1 DESCRIPTION
41 59
42This module implements a relatively simple "logging framework". It doesn't 60This module implements a relatively simple "logging framework". It doesn't
… …
49will be logged, unless you set C<PERL_ANYEVENT_VERBOSE> to a higher number 67will be logged, unless you set C<PERL_ANYEVENT_VERBOSE> to a higher number
50before starting your program, or change the logging level at runtime with 68before starting your program, or change the logging level at runtime with
51something like: 69something like:
52 70
53 use AnyEvent::Log; 71 use AnyEvent::Log;
54 AnyEvent::Log::FILTER->level ("info"); 72 $AnyEvent::Log::FILTER->level ("info");
55 73
56The design goal behind this module was to keep it simple (and small), 74The design goal behind this module was to keep it simple (and small),
57but make it powerful enough to be potentially useful for any module, and 75but make it powerful enough to be potentially useful for any module, and
58extensive enough for the most common tasks, such as logging to multiple 76extensive enough for the most common tasks, such as logging to multiple
59targets, or being able to log into a database. 77targets, or being able to log into a database.
60 78
79The module is also usable before AnyEvent itself is initialised, in which
80case some of the functionality might be reduced.
81
61The amount of documentation might indicate otherwise, but the module is 82The amount of documentation might indicate otherwise, but the runtime part
62still just below 300 lines of code. 83of the module is still just below 300 lines of code.
63 84
64=head1 LOGGING LEVELS 85=head1 LOGGING LEVELS
65 86
66Logging levels in this module range from C<1> (highest priority) to C<9> 87Logging levels in this module range from C<1> (highest priority) to C<9>
67(lowest priority). Note that the lowest numerical value is the highest 88(lowest priority). Note that the lowest numerical value is the highest
… …
69numerical value". 90numerical value".
70 91
71Instead of specifying levels by name you can also specify them by aliases: 92Instead of specifying levels by name you can also specify them by aliases:
72 93
73 LVL NAME SYSLOG PERL NOTE 94 LVL NAME SYSLOG PERL NOTE
74 1 fatal emerg exit aborts program! 95 1 fatal emerg exit system unusable, aborts program!
75 2 alert 96 2 alert failure in primary system
76 3 critical crit 97 3 critical crit failure in backup system
77 4 error err die 98 4 error err die non-urgent program errors, a bug
78 5 warn warning 99 5 warn warning possible problem, not necessarily error
79 6 note notice 100 6 note notice unusual conditions
80 7 info 101 7 info normal messages, no action required
81 8 debug 102 8 debug debugging messages for development
82 9 trace 103 9 trace copious tracing output
83 104
84As you can see, some logging levels have multiple aliases - the first one 105As you can see, some logging levels have multiple aliases - the first one
85is the "official" name, the second one the "syslog" name (if it differs) 106is the "official" name, the second one the "syslog" name (if it differs)
86and the third one the "perl" name, suggesting that you log C<die> messages 107and the third one the "perl" name, suggesting (only!) that you log C<die>
87at C<error> priority. 108messages at C<error> priority. The NOTE column tries to provide some
109rationale on how to chose a logging level.
110
111As a rough guideline, levels 1..3 are primarily meant for users of
112the program (admins, staff), and are the only logged to STDERR by
113default. Levels 4..6 are meant for users and developers alike, while
114levels 7..9 are usually meant for developers.
88 115
89You can normally only log a single message at highest priority level 116You can normally only log a single message at highest priority level
90(C<1>, C<fatal>), because logging a fatal message will also quit the 117(C<1>, C<fatal>), because logging a fatal message will also quit the
91program - so use it sparingly :) 118program - so use it sparingly :)
92 119
… …
108 135
109use Carp (); 136use Carp ();
110use POSIX (); 137use POSIX ();
111 138
112use AnyEvent (); BEGIN { AnyEvent::common_sense } 139use AnyEvent (); BEGIN { AnyEvent::common_sense }
113use AnyEvent::Util (); 140#use AnyEvent::Util (); need to load this in a delayed fashion, as it uses AE::log
114 141
115our $VERSION = $AnyEvent::VERSION; 142our $VERSION = $AnyEvent::VERSION;
116 143
117our ($COLLECT, $FILTER, $LOG); 144our ($COLLECT, $FILTER, $LOG);
118 145
… …
148=item AnyEvent::Log::log $level, $msg[, @args] 175=item AnyEvent::Log::log $level, $msg[, @args]
149 176
150Requests logging of the given C<$msg> with the given log level, and 177Requests logging of the given C<$msg> with the given log level, and
151returns true if the message was logged I<somewhere>. 178returns true if the message was logged I<somewhere>.
152 179
153For C<fatal> log levels, the program will abort. 180For loglevel C<fatal>, the program will abort.
154 181
155If only a C<$msg> is given, it is logged as-is. With extra C<@args>, the 182If only a C<$msg> is given, it is logged as-is. With extra C<@args>, the
156C<$msg> is interpreted as an sprintf format string. 183C<$msg> is interpreted as an sprintf format string.
157 184
158The C<$msg> should not end with C<\n>, but may if that is convenient for 185The C<$msg> should not end with C<\n>, but may if that is convenient for
… …
203 info => 7, 230 info => 7,
204 debug => 8, 231 debug => 8,
205 trace => 9, 232 trace => 9,
206); 233);
207 234
208sub now () { time } 235our $TIME_EXACT;
236
237sub exact_time($) {
238 $TIME_EXACT = shift;
239 *_ts = $AnyEvent::MODEL
240 ? $TIME_EXACT ? \&AE::now : \&AE::time
241 : sub () { $TIME_EXACT ? do { require Time::HiRes; Time::HiRes::time () } : time };
242}
243
244BEGIN {
245 exact_time 0;
246}
209 247
210AnyEvent::post_detect { 248AnyEvent::post_detect {
211 *now = \&AE::now; 249 exact_time $TIME_EXACT;
212}; 250};
213 251
214our @LEVEL2STR = qw(0 fatal alert crit error warn note info debug trace); 252our @LEVEL2STR = qw(0 fatal alert crit error warn note info debug trace);
215 253
216# time, ctx, level, msg 254# time, ctx, level, msg
… …
224 push @res, "$ts$ct$_\n"; 262 push @res, "$ts$ct$_\n";
225 $ct = " + "; 263 $ct = " + ";
226 } 264 }
227 265
228 join "", @res 266 join "", @res
267}
268
269sub fatal_exit() {
270 exit 1;
229} 271}
230 272
231sub _log { 273sub _log {
232 my ($ctx, $level, $format, @args) = @_; 274 my ($ctx, $level, $format, @args) = @_;
233 275
… …
249 # now get raw message, unless we have it already 291 # now get raw message, unless we have it already
250 unless ($now) { 292 unless ($now) {
251 $format = $format->() if ref $format; 293 $format = $format->() if ref $format;
252 $format = sprintf $format, @args if @args; 294 $format = sprintf $format, @args if @args;
253 $format =~ s/\n$//; 295 $format =~ s/\n$//;
254 $now = now; 296 $now = _ts;
255 }; 297 };
256 298
257 # format msg 299 # format msg
258 my $str = $ctx->[4] 300 my $str = $ctx->[4]
259 ? $ctx->[4]($now, $_[0], $level, $format) 301 ? $ctx->[4]($now, $_[0], $level, $format)
… …
268 } 310 }
269 } 311 }
270 } 312 }
271 while $ctx = pop @ctx; 313 while $ctx = pop @ctx;
272 314
273 exit 1 if $level <= 1; 315 fatal_exit if $level <= 1;
274 316
275 $success 317 $success
276} 318}
277 319
278sub log($$;@) { 320sub log($$;@) {
279 _log 321 _log
280 $CTX{ (caller)[0] } ||= _pkg_ctx +(caller)[0], 322 $CTX{ (caller)[0] } ||= _pkg_ctx +(caller)[0],
281 @_; 323 @_;
282} 324}
283 325
284*AnyEvent::log = *AE::log = \&log;
285
286=item $logger = AnyEvent::Log::logger $level[, \$enabled] 326=item $logger = AnyEvent::Log::logger $level[, \$enabled]
287 327
288Creates a code reference that, when called, acts as if the 328Creates a code reference that, when called, acts as if the
289C<AnyEvent::Log::log> function was called at this point with the given 329C<AnyEvent::Log::log> function was called at this point with the given
290level. C<$logger> is passed a C<$msg> and optional C<@args>, just as with 330level. C<$logger> is passed a C<$msg> and optional C<@args>, just as with
… …
354 394
355 $LOGGER{$logger+0} = $logger; 395 $LOGGER{$logger+0} = $logger;
356 396
357 _reassess $logger+0; 397 _reassess $logger+0;
358 398
399 require AnyEvent::Util unless $AnyEvent::Util::VERSION;
359 my $guard = AnyEvent::Util::guard { 400 my $guard = AnyEvent::Util::guard (sub {
360 # "clean up" 401 # "clean up"
361 delete $LOGGER{$logger+0}; 402 delete $LOGGER{$logger+0};
362 }; 403 });
363 404
364 sub { 405 sub {
365 $guard if 0; # keep guard alive, but don't cause runtime overhead 406 $guard if 0; # keep guard alive, but don't cause runtime overhead
366 407
367 _log $ctx, $level, @_ 408 _log $ctx, $level, @_
… …
372sub logger($;$) { 413sub logger($;$) {
373 _logger 414 _logger
374 $CTX{ (caller)[0] } ||= _pkg_ctx +(caller)[0], 415 $CTX{ (caller)[0] } ||= _pkg_ctx +(caller)[0],
375 @_ 416 @_
376} 417}
418
419=item AnyEvent::Log::exact_time $on
420
421By default, C<AnyEvent::Log> will use C<AE::now>, i.e. the cached
422eventloop time, for the log timestamps. After calling this function with a
423true value it will instead resort to C<AE::time>, i.e. fetch the current
424time on each log message. This only makes a difference for event loops
425that actually cache the time (such as L<EV> or L<AnyEvent::Loop>).
426
427This setting can be changed at any time by calling this function.
428
429Since C<AnyEvent::Log> has to work even before the L<AnyEvent> has been
430initialised, this switch will also decide whether to use C<CORE::time> or
431C<Time::HiRes::time> when logging a message before L<AnyEvent> becomes
432available.
377 433
378=back 434=back
379 435
380=head1 LOGGING CONTEXTS 436=head1 LOGGING CONTEXTS
381 437
… …
501This can be used to implement config-file (re-)loading: before loading a 557This can be used to implement config-file (re-)loading: before loading a
502configuration, reset all contexts. 558configuration, reset all contexts.
503 559
504=cut 560=cut
505 561
562our $ORIG_VERBOSE = $AnyEvent::VERBOSE;
563$AnyEvent::VERBOSE = 9;
564
506sub reset { 565sub reset {
507 # hard to kill complex data structures 566 # hard to kill complex data structures
508 # we "recreate" all package loggers and reset the hierarchy 567 # we "recreate" all package loggers and reset the hierarchy
509 while (my ($k, $v) = each %CTX) { 568 while (my ($k, $v) = each %CTX) {
510 @$v = ($k, (1 << 10) - 1 - 1, { }); 569 @$v = ($k, (1 << 10) - 1 - 1, { });
… …
513 } 572 }
514 573
515 @$_ = ($_->[0], (1 << 10) - 1 - 1) 574 @$_ = ($_->[0], (1 << 10) - 1 - 1)
516 for $LOG, $FILTER, $COLLECT; 575 for $LOG, $FILTER, $COLLECT;
517 576
518 $LOG->slaves; 577 #$LOG->slaves;
519 $LOG->title ('$AnyEvent::Log::LOG'); 578 $LOG->title ('$AnyEvent::Log::LOG');
520 $LOG->log_to_warn; 579 $LOG->log_to_warn;
521 580
522 $FILTER->slaves ($LOG); 581 $FILTER->slaves ($LOG);
523 $FILTER->title ('$AnyEvent::Log::FILTER'); 582 $FILTER->title ('$AnyEvent::Log::FILTER');
524 $FILTER->level ($AnyEvent::VERBOSE); 583 $FILTER->level ($ORIG_VERBOSE);
525 584
526 $COLLECT->slaves ($FILTER); 585 $COLLECT->slaves ($FILTER);
527 $COLLECT->title ('$AnyEvent::Log::COLLECT'); 586 $COLLECT->title ('$AnyEvent::Log::COLLECT');
528 587
529 _reassess; 588 _reassess;
530} 589}
590
591# override AE::log/logger
592*AnyEvent::log = *AE::log = \&log;
593*AnyEvent::logger = *AE::logger = \&logger;
594
595# convert AnyEvent loggers to AnyEvent::Log loggers
596$_->[0] = ctx $_->[0] # convert "pkg" to "ctx"
597 for values %LOGGER;
531 598
532# create the default logger contexts 599# create the default logger contexts
533$LOG = ctx undef; 600$LOG = ctx undef;
534$FILTER = ctx undef; 601$FILTER = ctx undef;
535$COLLECT = ctx undef; 602$COLLECT = ctx undef;
… …
834 901
835Needless(?) to say, if you do not want to be bitten by some evil person 902Needless(?) to say, if you do not want to be bitten by some evil person
836calling C<chdir>, the path should be absolute. Doesn't help with 903calling C<chdir>, the path should be absolute. Doesn't help with
837C<chroot>, but hey... 904C<chroot>, but hey...
838 905
839=item $ctx->log_to_syslog ([$log_flags]) 906=item $ctx->log_to_syslog ([$facility])
840 907
841Logs all messages via L<Sys::Syslog>, mapping C<trace> to C<debug> and all 908Logs all messages via L<Sys::Syslog>, mapping C<trace> to C<debug> and
842the others in the obvious way. If specified, then the C<$log_flags> are 909all the others in the obvious way. If specified, then the C<$facility> is
843simply or'ed onto the priority argument and can contain any C<LOG_xxx> 910used as the facility (C<user>, C<auth>, C<local0> and so on). The default
844flags valid for Sys::Syslog::syslog, except for the priority levels. 911facility is C<user>.
845 912
846Note that this function also sets a C<fmt_cb> - the logging part requires 913Note that this function also sets a C<fmt_cb> - the logging part requires
847an array reference with [$level, $str] as input. 914an array reference with [$level, $str] as input.
848 915
849=cut 916=cut
… …
892 0 959 0
893 }); 960 });
894} 961}
895 962
896sub log_to_syslog { 963sub log_to_syslog {
897 my ($ctx, $flags) = @_; 964 my ($ctx, $facility) = @_;
898 965
899 require Sys::Syslog; 966 require Sys::Syslog;
900 967
901 $ctx->fmt_cb (sub { 968 $ctx->fmt_cb (sub {
902 my $str = $_[3]; 969 my $str = $_[3];
903 $str =~ s/\n(?=.)/\n+ /g; 970 $str =~ s/\n(?=.)/\n+ /g;
904 971
905 [$_[2], "($_[1][0]) $str"] 972 [$_[2], "($_[1][0]) $str"]
906 }); 973 });
907 974
975 $facility ||= "user";
976
908 $ctx->log_cb (sub { 977 $ctx->log_cb (sub {
909 my $lvl = $_[0][0] < 9 ? $_[0][0] : 8; 978 my $lvl = $_[0][0] < 9 ? $_[0][0] : 8;
910 979
911 Sys::Syslog::syslog ($flags | ($lvl - 1), $_) 980 Sys::Syslog::syslog ("$facility|" . ($lvl - 1), $_)
912 for split /\n/, $_[0][1]; 981 for split /\n/, $_[0][1];
913 982
914 0 983 0
915 }); 984 });
916} 985}
… …
1088 My::Module=+,file=/tmp/mymodulelog 1157 My::Module=+,file=/tmp/mymodulelog
1089 1158
1090=back 1159=back
1091 1160
1092Any character can be escaped by prefixing it with a C<\> (backslash), as 1161Any character can be escaped by prefixing it with a C<\> (backslash), as
1093usual, so to log to a file containing a comma, colon, backslash and space in the 1162usual, so to log to a file containing a comma, colon, backslash and some
1094filename, you would do this: 1163spaces in the filename, you would do this:
1095 1164
1096 PERL_ANYEVENT_LOG='log=file=/some\ \:file\ with\,\ \\-escapes' 1165 PERL_ANYEVENT_LOG='log=file=/some\ \:file\ with\,\ \\-escapes'
1097 1166
1098Since whitespace (which includes newlines) is allowed, it is fine to 1167Since whitespace (which includes newlines) is allowed, it is fine to
1099specify multiple lines in C<PERL_ANYEVENT_LOG>, e.g.: 1168specify multiple lines in C<PERL_ANYEVENT_LOG>, e.g.:
… …
1133 while (/\G((?:[^,:[:space:]]+|::|\\.)+)/gc) { 1202 while (/\G((?:[^,:[:space:]]+|::|\\.)+)/gc) {
1134 for ("$1") { 1203 for ("$1") {
1135 if ($_ eq "stderr" ) { $ctx->log_to_warn; 1204 if ($_ eq "stderr" ) { $ctx->log_to_warn;
1136 } elsif (/^file=(.+)/ ) { $ctx->log_to_file ("$1"); 1205 } elsif (/^file=(.+)/ ) { $ctx->log_to_file ("$1");
1137 } elsif (/^path=(.+)/ ) { $ctx->log_to_path ("$1"); 1206 } elsif (/^path=(.+)/ ) { $ctx->log_to_path ("$1");
1138 } elsif (/syslog(?:=(.*))?/ ) { require Sys::Syslog; $ctx->log_to_syslog (eval "package Sys::Syslog; $1"); 1207 } elsif (/syslog(?:=(.*))?/ ) { require Sys::Syslog; $ctx->log_to_syslog ($1);
1139 } elsif ($_ eq "nolog" ) { $ctx->log_cb (undef); 1208 } elsif ($_ eq "nolog" ) { $ctx->log_cb (undef);
1140 } elsif (/^\+(.+)$/ ) { $ctx->attach ($pkg->("$1")); 1209 } elsif (/^\+(.+)$/ ) { $ctx->attach ($pkg->("$1"));
1141 } elsif ($_ eq "+" ) { $ctx->slaves; 1210 } elsif ($_ eq "+" ) { $ctx->slaves;
1142 } elsif ($_ eq "off" or $_ eq "0") { $ctx->level (0); 1211 } elsif ($_ eq "off" or $_ eq "0") { $ctx->level (0);
1143 } elsif ($_ eq "all" ) { $ctx->level ("all"); 1212 } elsif ($_ eq "all" ) { $ctx->level ("all");
… …
1196 1265
1197This writes them only when the global logging level allows it, because 1266This writes them only when the global logging level allows it, because
1198it is attached to the default context which is invoked I<after> global 1267it is attached to the default context which is invoked I<after> global
1199filtering. 1268filtering.
1200 1269
1201 $AnyEvent::Log::FILTER->attach 1270 $AnyEvent::Log::FILTER->attach (
1202 new AnyEvent::Log::Ctx log_to_file => $path); 1271 new AnyEvent::Log::Ctx log_to_file => $path);
1203 1272
1204 PERL_ANYEVENT_LOG=filter=+%filelogger:%filelogger=file=/some/path 1273 PERL_ANYEVENT_LOG=filter=+%filelogger:%filelogger=file=/some/path
1205 1274
1206This writes them regardless of the global logging level, because it is 1275This writes them regardless of the global logging level, because it is

Diff Legend

– Removed lines
+ Added lines
< Changed lines
> Changed lines