… | |
… | |
6 | |
6 | |
7 | Simple uses: |
7 | Simple uses: |
8 | |
8 | |
9 | use AnyEvent; |
9 | use AnyEvent; |
10 | |
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"; |
11 | AE::log trace => "going to call function abc"; |
19 | AE::log trace => "going to call function abc"; |
12 | AE::log debug => "the function returned 3"; |
|
|
13 | AE::log info => "file soandso successfully deleted"; |
|
|
14 | AE::log note => "wanted to create config, but config was already 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 |
|
|
20 | |
20 | |
21 | Log level overview: |
21 | Log level overview: |
22 | |
22 | |
23 | LVL NAME SYSLOG PERL NOTE |
23 | LVL NAME SYSLOG PERL NOTE |
24 | 1 fatal emerg exit system unusable, aborts program! |
24 | 1 fatal emerg exit system unusable, aborts program! |
… | |
… | |
61 | attempt to be "the" logging solution or even "a" logging solution for |
61 | attempt to be "the" logging solution or even "a" logging solution for |
62 | AnyEvent - AnyEvent simply creates logging messages internally, and this |
62 | AnyEvent - AnyEvent simply creates logging messages internally, and this |
63 | module more or less exposes the mechanism, with some extra spiff to allow |
63 | module more or less exposes the mechanism, with some extra spiff to allow |
64 | using it from other modules as well. |
64 | using it from other modules as well. |
65 | |
65 | |
66 | Remember that the default verbosity level is C<3> (C<critical>), so little |
66 | Remember that the default verbosity level is C<4> (C<error>), so only |
67 | will be logged, unless you set C<PERL_ANYEVENT_VERBOSE> to a higher number |
67 | errors and more important messages will be logged, unless you set |
68 | before starting your program, or change the logging level at runtime with |
68 | C<PERL_ANYEVENT_VERBOSE> to a higher number before starting your program |
69 | something like: |
69 | (C<AE_VERBOSE=5> is recommended during development), or change the logging |
|
|
70 | level at runtime with something like: |
70 | |
71 | |
71 | use AnyEvent::Log; |
72 | use AnyEvent::Log; |
72 | $AnyEvent::Log::FILTER->level ("info"); |
73 | $AnyEvent::Log::FILTER->level ("info"); |
73 | |
74 | |
74 | The design goal behind this module was to keep it simple (and small), |
75 | The design goal behind this module was to keep it simple (and small), |
75 | but make it powerful enough to be potentially useful for any module, and |
76 | but make it powerful enough to be potentially useful for any module, |
76 | extensive enough for the most common tasks, such as logging to multiple |
77 | and extensive enough for the most common tasks, such as logging to |
77 | targets, or being able to log into a database. |
78 | multiple targets, or being able to log into a database. |
78 | |
79 | |
79 | The module is also usable before AnyEvent itself is initialised, in which |
80 | The module is also usable before AnyEvent itself is initialised, in which |
80 | case some of the functionality might be reduced. |
81 | case some of the functionality might be reduced. |
81 | |
82 | |
82 | The amount of documentation might indicate otherwise, but the runtime part |
83 | The amount of documentation might indicate otherwise, but the runtime part |
… | |
… | |
115 | |
116 | |
116 | You can normally only log a message once at highest priority level (C<1>, |
117 | You can normally only log a message once at highest priority level (C<1>, |
117 | C<fatal>), because logging a fatal message will also quit the program - so |
118 | C<fatal>), because logging a fatal message will also quit the program - so |
118 | use it sparingly :) |
119 | use it sparingly :) |
119 | |
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 | |
120 | Some methods also offer some extra levels, such as C<0>, C<off>, C<none> |
125 | Some methods also offer some extra levels, such as C<0>, C<off>, C<none> |
121 | or C<all> - these are only valid for the methods that documented them. |
126 | or C<all> - these are only valid for the methods that documented them. |
122 | |
127 | |
123 | =head1 LOGGING FUNCTIONS |
128 | =head1 LOGGING FUNCTIONS |
124 | |
129 | |
… | |
… | |
148 | our ($COLLECT, $FILTER, $LOG); |
153 | our ($COLLECT, $FILTER, $LOG); |
149 | |
154 | |
150 | our ($now_int, $now_str1, $now_str2); |
155 | our ($now_int, $now_str1, $now_str2); |
151 | |
156 | |
152 | # Format Time, not public - yet? |
157 | # Format Time, not public - yet? |
153 | sub ft($) { |
158 | sub format_time($) { |
154 | my $i = int $_[0]; |
159 | my $i = int $_[0]; |
155 | my $f = sprintf "%06d", 1e6 * ($_[0] - $i); |
160 | my $f = sprintf "%06d", 1e6 * ($_[0] - $i); |
156 | |
161 | |
157 | ($now_int, $now_str1, $now_str2) = ($i, split /\x01/, POSIX::strftime "%Y-%m-%d %H:%M:%S.\x01 %z", localtime $i) |
162 | ($now_int, $now_str1, $now_str2) = ($i, split /\x01/, POSIX::strftime "%Y-%m-%d %H:%M:%S.\x01 %z", localtime $i) |
158 | if $now_int != $i; |
163 | if $now_int != $i; |
… | |
… | |
257 | }; |
262 | }; |
258 | |
263 | |
259 | our @LEVEL2STR = qw(0 fatal alert crit error warn note info debug trace); |
264 | our @LEVEL2STR = qw(0 fatal alert crit error warn note info debug trace); |
260 | |
265 | |
261 | # time, ctx, level, msg |
266 | # time, ctx, level, msg |
262 | sub _format($$$$) { |
267 | sub default_format($$$$) { |
263 | my $ts = ft $_[0]; |
268 | my $ts = format_time $_[0]; |
264 | my $ct = " "; |
269 | my $ct = " "; |
265 | |
270 | |
266 | my @res; |
271 | my @res; |
267 | |
272 | |
268 | for (split /\n/, sprintf "%-5s %s: %s", $LEVEL2STR[$_[2]], $_[1][0], $_[3]) { |
273 | for (split /\n/, sprintf "%-5s %s: %s", $LEVEL2STR[$_[2]], $_[1][0], $_[3]) { |
… | |
… | |
317 | }; |
322 | }; |
318 | |
323 | |
319 | # format msg |
324 | # format msg |
320 | my $str = $ctx->[4] |
325 | my $str = $ctx->[4] |
321 | ? $ctx->[4]($now, $_[0], $level, $format) |
326 | ? $ctx->[4]($now, $_[0], $level, $format) |
322 | : ($fmt[$level] ||= _format $now, $_[0], $level, $format); |
327 | : ($fmt[$level] ||= default_format $now, $_[0], $level, $format); |
323 | |
328 | |
324 | $success = 1; |
329 | $success = 1; |
325 | |
330 | |
326 | $ctx->[3]($str) |
331 | $ctx->[3]($str) |
327 | or push @ctx, values %{ $ctx->[2] }; # not consumed - propagate |
332 | or push @ctx, values %{ $ctx->[2] }; # not consumed - propagate |
… | |
… | |
449 | Since C<AnyEvent::Log> has to work even before the L<AnyEvent> has been |
454 | Since C<AnyEvent::Log> has to work even before the L<AnyEvent> has been |
450 | initialised, this switch will also decide whether to use C<CORE::time> or |
455 | initialised, this switch will also decide whether to use C<CORE::time> or |
451 | C<Time::HiRes::time> when logging a message before L<AnyEvent> becomes |
456 | C<Time::HiRes::time> when logging a message before L<AnyEvent> becomes |
452 | available. |
457 | available. |
453 | |
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 | |
454 | =back |
494 | =back |
455 | |
495 | |
456 | =head1 LOGGING CONTEXTS |
496 | =head1 LOGGING CONTEXTS |
457 | |
497 | |
458 | This module associates every log message with a so-called I<logging |
498 | This module associates every log message with a so-called I<logging |
… | |
… | |
859 | the logging (which consists of formatting the message and printing it or |
899 | the logging (which consists of formatting the message and printing it or |
860 | whatever it wants to do with it). |
900 | whatever it wants to do with it). |
861 | |
901 | |
862 | =over 4 |
902 | =over 4 |
863 | |
903 | |
864 | =item $ctx->log_cb ($cb->($str) |
904 | =item $ctx->log_cb ($cb->($str)) |
865 | |
905 | |
866 | Replaces the logging callback on the context (C<undef> disables the |
906 | Replaces the logging callback on the context (C<undef> disables the |
867 | logging callback). |
907 | logging callback). |
868 | |
908 | |
869 | The logging callback is responsible for handling formatted log messages |
909 | The logging callback is responsible for handling formatted log messages |
… | |
… | |
894 | |
934 | |
895 | Replaces the formatting callback on the context (C<undef> restores the |
935 | Replaces the formatting callback on the context (C<undef> restores the |
896 | default formatter). |
936 | default formatter). |
897 | |
937 | |
898 | The callback is passed the (possibly fractional) timestamp, the original |
938 | The callback is passed the (possibly fractional) timestamp, the original |
899 | logging context, the (numeric) logging level and the raw message string |
939 | logging context (object, not title), the (numeric) logging level and |
900 | and needs to return a formatted log message. In most cases this will be a |
940 | the raw message string and needs to return a formatted log message. In |
901 | string, but it could just as well be an array reference that just stores |
941 | most cases this will be a string, but it could just as well be an array |
902 | the values. |
942 | reference that just stores the values. |
903 | |
943 | |
904 | If, for some reason, you want to use C<caller> to find out more baout the |
944 | If, for some reason, you want to use C<caller> to find out more about the |
905 | logger then you should walk up the call stack until you are no longer |
945 | logger then you should walk up the call stack until you are no longer |
906 | inside the C<AnyEvent::Log> package. |
946 | inside the C<AnyEvent::Log> package. |
907 | |
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 | |
908 | Example: format just the raw message, with numeric log level in angle |
962 | Example: format just the raw message, with numeric log level in angle |
909 | brackets. |
963 | brackets. |
910 | |
964 | |
911 | $ctx->fmt_cb (sub { |
965 | $ctx->fmt_cb (sub { |
912 | my ($time, $ctx, $lvl, $msg) = @_; |
966 | my ($time, $ctx, $lvl, $msg) = @_; |
913 | |
967 | |
914 | "<$lvl>$msg\n" |
968 | "<$lvl>$msg\n" |
915 | }); |
969 | }); |
916 | |
970 | |
917 | Example: return an array reference with just the log values, and use |
971 | Example: return an array reference with just the log values, and use |
918 | C<PApp::SQL::sql_exec> to store the emssage in a database. |
972 | C<PApp::SQL::sql_exec> to store the message in a database. |
919 | |
973 | |
920 | $ctx->fmt_cb (sub { \@_ }); |
974 | $ctx->fmt_cb (sub { \@_ }); |
921 | $ctx->log_cb (sub { |
975 | $ctx->log_cb (sub { |
922 | my ($msg) = @_; |
976 | my ($msg) = @_; |
923 | |
977 | |
… | |
… | |
935 | Sets the C<log_cb> to simply use C<CORE::warn> to report any messages |
989 | Sets the C<log_cb> to simply use C<CORE::warn> to report any messages |
936 | (usually this logs to STDERR). |
990 | (usually this logs to STDERR). |
937 | |
991 | |
938 | =item $ctx->log_to_file ($path) |
992 | =item $ctx->log_to_file ($path) |
939 | |
993 | |
940 | Sets the C<log_cb> to log to a file (by appending), unbuffered. |
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. |
941 | |
996 | |
942 | =item $ctx->log_to_path ($path) |
997 | =item $ctx->log_to_path ($path) |
943 | |
998 | |
944 | Same as C<< ->log_to_file >>, but opens the file for each message. This |
999 | Same as C<< ->log_to_file >>, but opens the file for each message. This |
945 | is much slower, but allows you to change/move/rename/delete the file at |
1000 | is much slower, but allows you to change/move/rename/delete the file at |
… | |
… | |
980 | warn shift; |
1035 | warn shift; |
981 | 0 |
1036 | 0 |
982 | }); |
1037 | }); |
983 | } |
1038 | } |
984 | |
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 | |
985 | sub log_to_file { |
1124 | sub log_to_file { |
986 | my ($ctx, $path) = @_; |
1125 | my ($ctx, $path) = @_; |
987 | |
1126 | |
988 | open my $fh, ">>", $path |
1127 | _log_to_disk $ctx, $path, 1; |
989 | or die "$path: $!"; |
|
|
990 | |
|
|
991 | $ctx->log_cb (sub { |
|
|
992 | syswrite $fh, shift; |
|
|
993 | 0 |
|
|
994 | }); |
|
|
995 | } |
1128 | } |
996 | |
1129 | |
997 | sub log_to_path { |
1130 | sub log_to_path { |
998 | my ($ctx, $path) = @_; |
1131 | my ($ctx, $path) = @_; |
999 | |
1132 | |
1000 | $ctx->log_cb (sub { |
1133 | _log_to_disk $ctx, $path, 0; |
1001 | open my $fh, ">>", $path |
|
|
1002 | or die "$path: $!"; |
|
|
1003 | |
|
|
1004 | syswrite $fh, shift; |
|
|
1005 | 0 |
|
|
1006 | }); |
|
|
1007 | } |
1134 | } |
1008 | |
1135 | |
1009 | sub log_to_syslog { |
1136 | sub log_to_syslog { |
1010 | my ($ctx, $facility) = @_; |
1137 | my ($ctx, $facility) = @_; |
1011 | |
1138 | |
… | |
… | |
1040 | =over 4 |
1167 | =over 4 |
1041 | |
1168 | |
1042 | =item $ctx->log ($level, $msg[, @params]) |
1169 | =item $ctx->log ($level, $msg[, @params]) |
1043 | |
1170 | |
1044 | Same as C<AnyEvent::Log::log>, but uses the given context as log context. |
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"); |
1045 | |
1176 | |
1046 | =item $logger = $ctx->logger ($level[, \$enabled]) |
1177 | =item $logger = $ctx->logger ($level[, \$enabled]) |
1047 | |
1178 | |
1048 | Same as C<AnyEvent::Log::logger>, but uses the given context as log |
1179 | Same as C<AnyEvent::Log::logger>, but uses the given context as log |
1049 | context. |
1180 | context. |
… | |
… | |
1096 | =item C<%name> |
1227 | =item C<%name> |
1097 | |
1228 | |
1098 | Context names starting with a C<%> are anonymous contexts created when the |
1229 | Context names starting with a C<%> are anonymous contexts created when the |
1099 | name is first mentioned. The difference to package contexts is that by |
1230 | name is first mentioned. The difference to package contexts is that by |
1100 | default they have no attached slaves. |
1231 | default they have no attached slaves. |
|
|
1232 | |
|
|
1233 | This makes it possible to create new log contexts that can be refered to |
|
|
1234 | multiple times by name within the same log specification. |
1101 | |
1235 | |
1102 | =item a perl package name |
1236 | =item a perl package name |
1103 | |
1237 | |
1104 | Any other string references the logging context associated with the given |
1238 | Any other string references the logging context associated with the given |
1105 | Perl C<package>. In the unlikely case where you want to specify a package |
1239 | Perl C<package>. In the unlikely case where you want to specify a package |
… | |
… | |
1283 | if (/\G(.+)/g) { |
1417 | if (/\G(.+)/g) { |
1284 | die "PERL_ANYEVENT_LOG ($spec): parse error at '$1'\n"; |
1418 | die "PERL_ANYEVENT_LOG ($spec): parse error at '$1'\n"; |
1285 | } |
1419 | } |
1286 | } |
1420 | } |
1287 | |
1421 | |
1288 | 1; |
|
|
1289 | |
|
|
1290 | =head1 EXAMPLES |
1422 | =head1 EXAMPLES |
1291 | |
1423 | |
1292 | This section shows some common configurations, both as code, and as |
1424 | This section shows some common configurations, both as code, and as |
1293 | C<PERL_ANYEVENT_LOG> string. |
1425 | C<PERL_ANYEVENT_LOG> string. |
1294 | |
1426 | |
… | |
… | |
1367 | assumes the log level for AnyEvent::Debug hasn't been changed from the |
1499 | assumes the log level for AnyEvent::Debug hasn't been changed from the |
1368 | default. |
1500 | default. |
1369 | |
1501 | |
1370 | =back |
1502 | =back |
1371 | |
1503 | |
|
|
1504 | =head1 ASYNCHRONOUS DISK I/O |
|
|
1505 | |
|
|
1506 | This module uses L<AnyEvent::IO> to actually write log messages (in |
|
|
1507 | C<log_to_file> and C<log_to_path>), so it doesn't block your program when |
|
|
1508 | the disk is busy and a non-blocking L<AnyEvent::IO> backend is available. |
|
|
1509 | |
1372 | =head1 AUTHOR |
1510 | =head1 AUTHOR |
1373 | |
1511 | |
1374 | Marc Lehmann <schmorp@schmorp.de> |
1512 | Marc Lehmann <schmorp@schmorp.de> |
1375 | http://home.schmorp.de/ |
1513 | http://anyevent.schmorp.de |
1376 | |
1514 | |
1377 | =cut |
1515 | =cut |
1378 | |
1516 | |
|
|
1517 | 1 |
|
|
1518 | |