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.54 by root, Tue Mar 27 23:47:57 2012 UTC vs.
Revision 1.66 by root, Mon Mar 11 20:48:19 2019 UTC

… …
33 33
34"Complex" uses (for speed sensitive code, e.g. trace/debug messages): 34"Complex" uses (for speed sensitive code, e.g. trace/debug messages):
35 35
36 use AnyEvent::Log; 36 use AnyEvent::Log;
37 37
38 my $tracer = AnyEvent::Log::logger trace => \$my $trace; 38 my $tracer = AnyEvent::Log::logger trace => \my $trace;
39 39
40 $tracer->("i am here") if $trace; 40 $tracer->("i am here") if $trace;
41 $tracer->(sub { "lots of data: " . Dumper $self }) if $trace; 41 $tracer->(sub { "lots of data: " . Dumper $self }) if $trace;
42 42
43Configuration (also look at the EXAMPLES section): 43Configuration (also look at the EXAMPLES section):
… …
71 71
72 use AnyEvent::Log; 72 use AnyEvent::Log;
73 $AnyEvent::Log::FILTER->level ("info"); 73 $AnyEvent::Log::FILTER->level ("info");
74 74
75The design goal behind this module was to keep it simple (and small), 75The design goal behind this module was to keep it simple (and small),
76but make it powerful enough to be potentially useful for any module, and 76but make it powerful enough to be potentially useful for any module,
77extensive enough for the most common tasks, such as logging to multiple 77and extensive enough for the most common tasks, such as logging to
78targets, or being able to log into a database. 78multiple targets, or being able to log into a database.
79 79
80The module is also usable before AnyEvent itself is initialised, in which 80The module is also usable before AnyEvent itself is initialised, in which
81case some of the functionality might be reduced. 81case some of the functionality might be reduced.
82 82
83The amount of documentation might indicate otherwise, but the runtime part 83The amount of documentation might indicate otherwise, but the runtime part
… …
153our ($COLLECT, $FILTER, $LOG); 153our ($COLLECT, $FILTER, $LOG);
154 154
155our ($now_int, $now_str1, $now_str2); 155our ($now_int, $now_str1, $now_str2);
156 156
157# Format Time, not public - yet? 157# Format Time, not public - yet?
158sub ft($) { 158sub 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
264our @LEVEL2STR = qw(0 fatal alert crit error warn note info debug trace); 264our @LEVEL2STR = qw(0 fatal alert crit error warn note info debug trace);
265 265
266# time, ctx, level, msg 266# time, ctx, level, msg
267sub _format($$$$) { 267sub 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
… …
454Since C<AnyEvent::Log> has to work even before the L<AnyEvent> has been 454Since C<AnyEvent::Log> has to work even before the L<AnyEvent> has been
455initialised, this switch will also decide whether to use C<CORE::time> or 455initialised, this switch will also decide whether to use C<CORE::time> or
456C<Time::HiRes::time> when logging a message before L<AnyEvent> becomes 456C<Time::HiRes::time> when logging a message before L<AnyEvent> becomes
457available. 457available.
458 458
459=item AnyEvent::Log::format_time $timestamp
460
461Formats a timestamp as returned by C<< AnyEvent->now >> or C<<
462AnyEvent->time >> or many other functions in the same way as
463C<AnyEvent::Log> does.
464
465In your main program (as opposed to in your module) you can override
466the default timestamp display format by loading this module and then
467redefining this function.
468
469Most commonly, this function can be used in formatting callbacks.
470
471=item AnyEvent::Log::default_format $time, $ctx, $level, $msg
472
473Format a log message using the given timestamp, logging context, log level
474and log message.
475
476This is the formatting function used to format messages when no custom
477function is provided.
478
479In your main program (as opposed to in your module) you can override the
480default message format by loading this module and then redefining this
481function.
482
483=item AnyEvent::Log::fatal_exit()
484
485This is the function that is called after logging a C<fatal> log
486message. It must not return.
487
488The default implementation simply calls C<exit 1>.
489
490In your main program (as opposed to in your module) you can override
491the fatal exit function by loading this module and then redefining this
492function. Make sure you don't return.
493
459=back 494=back
460 495
461=head1 LOGGING CONTEXTS 496=head1 LOGGING CONTEXTS
462 497
463This module associates every log message with a so-called I<logging 498This module associates every log message with a so-called I<logging
… …
864the logging (which consists of formatting the message and printing it or 899the logging (which consists of formatting the message and printing it or
865whatever it wants to do with it). 900whatever 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
871Replaces the logging callback on the context (C<undef> disables the 906Replaces the logging callback on the context (C<undef> disables the
872logging callback). 907logging callback).
873 908
874The logging callback is responsible for handling formatted log messages 909The logging callback is responsible for handling formatted log messages
… …
908 943
909If, for some reason, you want to use C<caller> to find out more about the 944If, for some reason, you want to use C<caller> to find out more about the
910logger then you should walk up the call stack until you are no longer 945logger then you should walk up the call stack until you are no longer
911inside the C<AnyEvent::Log> package. 946inside the C<AnyEvent::Log> package.
912 947
948To implement your own logging callback, you might find the
949C<AnyEvent::Log::format_time> and C<AnyEvent::Log::default_format>
950functions useful.
951
952Example: format the message just as AnyEvent::Log would, by letting
953AnyEvent::Log do the work. This is a good basis to design a formatting
954callback 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
913Example: format just the raw message, with numeric log level in angle 962Example: format just the raw message, with numeric log level in angle
914brackets. 963brackets.
915 964
916 $ctx->fmt_cb (sub { 965 $ctx->fmt_cb (sub {
917 my ($time, $ctx, $lvl, $msg) = @_; 966 my ($time, $ctx, $lvl, $msg) = @_;
… …
940Sets the C<log_cb> to simply use C<CORE::warn> to report any messages 989Sets 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
945Sets the C<log_cb> to log to a file (by appending), unbuffered. 994Sets the C<log_cb> to log to a file (by appending), unbuffered. The
995function 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
949Same as C<< ->log_to_file >>, but opens the file for each message. This 999Same as C<< ->log_to_file >>, but opens the file for each message. This
950is much slower, but allows you to change/move/rename/delete the file at 1000is 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.
1042sub _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
990sub log_to_file { 1124sub 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
1002sub log_to_path { 1130sub 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
1014sub log_to_syslog { 1136sub log_to_syslog {
1015 my ($ctx, $facility) = @_; 1137 my ($ctx, $facility) = @_;
1016 1138
… …
1105=item C<%name> 1227=item C<%name>
1106 1228
1107Context names starting with a C<%> are anonymous contexts created when the 1229Context names starting with a C<%> are anonymous contexts created when the
1108name is first mentioned. The difference to package contexts is that by 1230name is first mentioned. The difference to package contexts is that by
1109default they have no attached slaves. 1231default they have no attached slaves.
1232
1233This makes it possible to create new log contexts that can be refered to
1234multiple times by name within the same log specification.
1110 1235
1111=item a perl package name 1236=item a perl package name
1112 1237
1113Any other string references the logging context associated with the given 1238Any other string references the logging context associated with the given
1114Perl C<package>. In the unlikely case where you want to specify a package 1239Perl C<package>. In the unlikely case where you want to specify a package
… …
1374assumes the log level for AnyEvent::Debug hasn't been changed from the 1499assumes the log level for AnyEvent::Debug hasn't been changed from the
1375default. 1500default.
1376 1501
1377=back 1502=back
1378 1503
1504=head1 ASYNCHRONOUS DISK I/O
1505
1506This module uses L<AnyEvent::IO> to actually write log messages (in
1507C<log_to_file> and C<log_to_path>), so it doesn't block your program when
1508the disk is busy and a non-blocking L<AnyEvent::IO> backend is available.
1509
1379=head1 AUTHOR 1510=head1 AUTHOR
1380 1511
1381 Marc Lehmann <schmorp@schmorp.de> 1512 Marc Lehmann <schmorp@schmorp.de>
1382 http://home.schmorp.de/ 1513 http://anyevent.schmorp.de
1383 1514
1384=cut 1515=cut
1385 1516
13861 15171
1387 1518

Diff Legend

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