… | |
… | |
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 |
11 | AE::log fatal => "No config found, cannot continue!"; # never returns |
12 | AE::log alert => "the battery died"; |
12 | AE::log alert => "The battery died!"; |
13 | AE::log crit => "the battery temperature is too hot"; |
13 | AE::log crit => "The battery temperature is too hot!"; |
14 | AE::log error => "division by zero attempted"; |
14 | AE::log error => "Division by zero attempted."; |
15 | AE::log warn => "couldn't delete the file"; |
15 | AE::log warn => "Couldn't delete the file."; |
16 | AE::log note => "wanted to create config, but config already exists"; |
16 | AE::log note => "Wanted to create config, but config already exists."; |
17 | AE::log info => "file soandso successfully deleted"; |
17 | AE::log info => "File soandso successfully deleted."; |
18 | AE::log debug => "the function returned 3"; |
18 | AE::log debug => "the function returned 3"; |
19 | AE::log trace => "going to call function abc"; |
19 | AE::log trace => "going to call function abc"; |
20 | |
20 | |
21 | Log level overview: |
21 | Log level overview: |
22 | |
22 | |
… | |
… | |
71 | |
71 | |
72 | use AnyEvent::Log; |
72 | use AnyEvent::Log; |
73 | $AnyEvent::Log::FILTER->level ("info"); |
73 | $AnyEvent::Log::FILTER->level ("info"); |
74 | |
74 | |
75 | 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), |
76 | 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, |
77 | 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 |
78 | targets, or being able to log into a database. |
78 | multiple targets, or being able to log into a database. |
79 | |
79 | |
80 | 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 |
81 | case some of the functionality might be reduced. |
81 | case some of the functionality might be reduced. |
82 | |
82 | |
83 | The amount of documentation might indicate otherwise, but the runtime part |
83 | The amount of documentation might indicate otherwise, but the runtime part |
… | |
… | |
153 | our ($COLLECT, $FILTER, $LOG); |
153 | our ($COLLECT, $FILTER, $LOG); |
154 | |
154 | |
155 | our ($now_int, $now_str1, $now_str2); |
155 | our ($now_int, $now_str1, $now_str2); |
156 | |
156 | |
157 | # Format Time, not public - yet? |
157 | # Format Time, not public - yet? |
158 | sub ft($) { |
158 | sub format_time($) { |
159 | my $i = int $_[0]; |
159 | my $i = int $_[0]; |
160 | my $f = sprintf "%06d", 1e6 * ($_[0] - $i); |
160 | my $f = sprintf "%06d", 1e6 * ($_[0] - $i); |
161 | |
161 | |
162 | ($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) |
163 | if $now_int != $i; |
163 | if $now_int != $i; |
… | |
… | |
262 | }; |
262 | }; |
263 | |
263 | |
264 | 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); |
265 | |
265 | |
266 | # time, ctx, level, msg |
266 | # time, ctx, level, msg |
267 | sub _format($$$$) { |
267 | sub default_format($$$$) { |
268 | my $ts = ft $_[0]; |
268 | my $ts = format_time $_[0]; |
269 | my $ct = " "; |
269 | my $ct = " "; |
270 | |
270 | |
271 | my @res; |
271 | my @res; |
272 | |
272 | |
273 | 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]) { |
… | |
… | |
322 | }; |
322 | }; |
323 | |
323 | |
324 | # format msg |
324 | # format msg |
325 | my $str = $ctx->[4] |
325 | my $str = $ctx->[4] |
326 | ? $ctx->[4]($now, $_[0], $level, $format) |
326 | ? $ctx->[4]($now, $_[0], $level, $format) |
327 | : ($fmt[$level] ||= _format $now, $_[0], $level, $format); |
327 | : ($fmt[$level] ||= default_format $now, $_[0], $level, $format); |
328 | |
328 | |
329 | $success = 1; |
329 | $success = 1; |
330 | |
330 | |
331 | $ctx->[3]($str) |
331 | $ctx->[3]($str) |
332 | or push @ctx, values %{ $ctx->[2] }; # not consumed - propagate |
332 | or push @ctx, values %{ $ctx->[2] }; # not consumed - propagate |
… | |
… | |
454 | 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 |
455 | 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 |
456 | 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 |
457 | available. |
457 | available. |
458 | |
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 | |
459 | =back |
494 | =back |
460 | |
495 | |
461 | =head1 LOGGING CONTEXTS |
496 | =head1 LOGGING CONTEXTS |
462 | |
497 | |
463 | 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 |
… | |
… | |
864 | 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 |
865 | whatever it wants to do with it). |
900 | whatever it wants to do with it). |
866 | |
901 | |
867 | =over 4 |
902 | =over 4 |
868 | |
903 | |
869 | =item $ctx->log_cb ($cb->($str) |
904 | =item $ctx->log_cb ($cb->($str)) |
870 | |
905 | |
871 | Replaces the logging callback on the context (C<undef> disables the |
906 | Replaces the logging callback on the context (C<undef> disables the |
872 | logging callback). |
907 | logging callback). |
873 | |
908 | |
874 | The logging callback is responsible for handling formatted log messages |
909 | The logging callback is responsible for handling formatted log messages |
… | |
… | |
908 | |
943 | |
909 | If, for some reason, you want to use C<caller> to find out more about the |
944 | If, for some reason, you want to use C<caller> to find out more about the |
910 | 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 |
911 | inside the C<AnyEvent::Log> package. |
946 | inside the C<AnyEvent::Log> package. |
912 | |
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 | |
913 | 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 |
914 | brackets. |
963 | brackets. |
915 | |
964 | |
916 | $ctx->fmt_cb (sub { |
965 | $ctx->fmt_cb (sub { |
917 | my ($time, $ctx, $lvl, $msg) = @_; |
966 | my ($time, $ctx, $lvl, $msg) = @_; |
… | |
… | |
940 | 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 |
941 | (usually this logs to STDERR). |
990 | (usually this logs to STDERR). |
942 | |
991 | |
943 | =item $ctx->log_to_file ($path) |
992 | =item $ctx->log_to_file ($path) |
944 | |
993 | |
945 | 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. |
946 | |
996 | |
947 | =item $ctx->log_to_path ($path) |
997 | =item $ctx->log_to_path ($path) |
948 | |
998 | |
949 | 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 |
950 | 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 |
… | |
… | |
985 | warn shift; |
1035 | warn shift; |
986 | 0 |
1036 | 0 |
987 | }); |
1037 | }); |
988 | } |
1038 | } |
989 | |
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 | |
990 | sub log_to_file { |
1124 | sub log_to_file { |
991 | my ($ctx, $path) = @_; |
1125 | my ($ctx, $path) = @_; |
992 | |
1126 | |
993 | open my $fh, ">>", $path |
1127 | _log_to_disk $ctx, $path, 1; |
994 | or die "$path: $!"; |
|
|
995 | |
|
|
996 | $ctx->log_cb (sub { |
|
|
997 | syswrite $fh, shift; |
|
|
998 | 0 |
|
|
999 | }); |
|
|
1000 | } |
1128 | } |
1001 | |
1129 | |
1002 | sub log_to_path { |
1130 | sub log_to_path { |
1003 | my ($ctx, $path) = @_; |
1131 | my ($ctx, $path) = @_; |
1004 | |
1132 | |
1005 | $ctx->log_cb (sub { |
1133 | _log_to_disk $ctx, $path, 0; |
1006 | open my $fh, ">>", $path |
|
|
1007 | or die "$path: $!"; |
|
|
1008 | |
|
|
1009 | syswrite $fh, shift; |
|
|
1010 | 0 |
|
|
1011 | }); |
|
|
1012 | } |
1134 | } |
1013 | |
1135 | |
1014 | sub log_to_syslog { |
1136 | sub log_to_syslog { |
1015 | my ($ctx, $facility) = @_; |
1137 | my ($ctx, $facility) = @_; |
1016 | |
1138 | |
… | |
… | |
1374 | assumes the log level for AnyEvent::Debug hasn't been changed from the |
1496 | assumes the log level for AnyEvent::Debug hasn't been changed from the |
1375 | default. |
1497 | default. |
1376 | |
1498 | |
1377 | =back |
1499 | =back |
1378 | |
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 | |
1379 | =head1 AUTHOR |
1507 | =head1 AUTHOR |
1380 | |
1508 | |
1381 | Marc Lehmann <schmorp@schmorp.de> |
1509 | Marc Lehmann <schmorp@schmorp.de> |
1382 | http://home.schmorp.de/ |
1510 | http://anyevent.schmorp.de |
1383 | |
1511 | |
1384 | =cut |
1512 | =cut |
1385 | |
1513 | |
1386 | 1 |
1514 | 1 |
1387 | |
1515 | |