ViewVC Help

View File | Revision Log | Show Annotations | Download File

/cvs/AnyEvent/lib/AnyEvent/Log.pm

Comparing AnyEvent/lib/AnyEvent/Log.pm (file contents):
Revision 1.12 by root, Sat Aug 20 01:33:10 2011 UTC vs.
Revision 1.66 by root, Mon Mar 11 20:48:19 2019 UTC

…		…
2		2
3	AnyEvent::Log - simple logging "framework"	3	AnyEvent::Log - simple logging "framework"
4		4
5	=head1 SYNOPSIS	5	=head1 SYNOPSIS
6		6
7	# simple use	7	Simple uses:
		8
8	use AnyEvent;	9	use AnyEvent;
9		10
10	AE::log debug => "hit my knee";	11	AE::log fatal => "No config found, cannot continue!"; # never returns
11	AE::log warn => "it's a bit too hot";	12	AE::log alert => "The battery died!";
12	AE::log error => "the flag was false!";	13	AE::log crit => "The battery temperature is too hot!";
13	AE::log fatal => "the bit toggled! run!";	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";
		19	AE::log trace => "going to call function abc";
14		20
15	# "complex" use	21	Log 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
		34	"Complex" uses (for speed sensitive code, e.g. trace/debug messages):
		35
16	use AnyEvent::Log;	36	use AnyEvent::Log;
17		37
18	my $tracer = AnyEvent::Log::logger trace => \$my $trace;	38	my $tracer = AnyEvent::Log::logger trace => \my $trace;
19		39
20	$tracer->("i am here") if $trace;	40	$tracer->("i am here") if $trace;
21	$tracer->(sub { "lots of data: " . Dumper $self }) if $trace;	41	$tracer->(sub { "lots of data: " . Dumper $self }) if $trace;
22		42
23	# configuration	43	Configuration (also look at the EXAMPLES section):
24		44
25	# set logging for this package to maximum	45	# set logging for the current package to errors and higher only
26	AnyEvent::Log::ctx->level ("all");	46	AnyEvent::Log::ctx->level ("error");
27		47
28	# set logging globally to anything below debug	48	# set logging level to suppress anything below "notice"
29	(AnyEvent::Log::ctx "")->level ("notice");	49	$AnyEvent::Log::FILTER->level ("notice");
30		50
31	# see also EXAMPLES, below	51	# send all critical and higher priority messages to syslog,
32		52	# regardless of (most) other settings
33	# disable logging for package "AnyEvent" and all packages below it	53	$AnyEvent::Log::COLLECT->attach (new AnyEvent::Log::Ctx
34	AnyEvent->AnyEvent::Log::ctx->level (0);	54	level => "critical",
35		55	log_to_syslog => "user",
36	# log everything below debug to a file, for the whole program	56	);
37	my $ctx = AnyEvent::Log::ctx;
38	$ctx->log_cb (sub { print FILE shift; 0 });
39	(AnyEvent::Log::ctx "")->add ($ctx);
40		57
41	=head1 DESCRIPTION	58	=head1 DESCRIPTION
42		59
43	This module implements a relatively simple "logging framework". It doesn't	60	This module implements a relatively simple "logging framework". It doesn't
44	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
45	AnyEvent - AnyEvent simply creates logging messages internally, and this	62	AnyEvent - AnyEvent simply creates logging messages internally, and this
46	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
47	using it from other modules as well.	64	using it from other modules as well.
48		65
49	Remember that the default verbosity level is C<0>, so nothing will be	66	Remember that the default verbosity level is C<4> (C<error>), so only
50	logged, unless you set C<PERL_ANYEVENT_VERBOSE> to a higher number before	67	errors and more important messages will be logged, unless you set
51	starting your program, or change the logging level at runtime with	68	C<PERL_ANYEVENT_VERBOSE> to a higher number before starting your program
52	something like:	69	(C<AE_VERBOSE=5> is recommended during development), or change the logging
		70	level at runtime with something like:
53		71
54	use AnyEvent;	72	use AnyEvent::Log;
55	(AnyEvent::Log::ctx "")->level ("info");	73	$AnyEvent::Log::FILTER->level ("info");
56		74
57	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),
58	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,
59	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
60	targets, or being able to log into a database.	78	multiple targets, or being able to log into a database.
		79
		80	The module is also usable before AnyEvent itself is initialised, in which
		81	case some of the functionality might be reduced.
		82
		83	The amount of documentation might indicate otherwise, but the runtime part
		84	of the module is still just below 300 lines of code.
		85
		86	=head1 LOGGING LEVELS
		87
		88	Logging levels in this module range from C<1> (highest priority) to C<9>
		89	(lowest priority). Note that the lowest numerical value is the highest
		90	priority, so when this document says "higher priority" it means "lower
		91	numerical value".
		92
		93	Instead of specifying levels by name you can also specify them by aliases:
		94
		95	LVL NAME SYSLOG PERL NOTE
		96	1 fatal emerg exit system unusable, aborts program!
		97	2 alert failure in primary system
		98	3 critical crit failure in backup system
		99	4 error err die non-urgent program errors, a bug
		100	5 warn warning possible problem, not necessarily error
		101	6 note notice unusual conditions
		102	7 info normal messages, no action required
		103	8 debug debugging messages for development
		104	9 trace copious tracing output
		105
		106	As you can see, some logging levels have multiple aliases - the first one
		107	is the "official" name, the second one the "syslog" name (if it differs)
		108	and the third one the "perl" name, suggesting (only!) that you log C<die>
		109	messages at C<error> priority. The NOTE column tries to provide some
		110	rationale on how to chose a logging level.
		111
		112	As a rough guideline, levels 1..3 are primarily meant for users of the
		113	program (admins, staff), and are the only ones logged to STDERR by
		114	default. Levels 4..6 are meant for users and developers alike, while
		115	levels 7..9 are usually meant for developers.
		116
		117	You can normally only log a message once at highest priority level (C<1>,
		118	C<fatal>), because logging a fatal message will also quit the program - so
		119	use it sparingly :)
		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
		125	Some methods also offer some extra levels, such as C<0>, C<off>, C<none>
		126	or C<all> - these are only valid for the methods that documented them.
61		127
62	=head1 LOGGING FUNCTIONS	128	=head1 LOGGING FUNCTIONS
63		129
64	These functions allow you to log messages. They always use the caller's	130	The following functions allow you to log messages. They always use the
65	package as a "logging module/source". Also, the main logging function is	131	caller's package as a "logging context". Also, the main logging function,
66	callable as C<AnyEvent::log> or C<AE::log> when the C<AnyEvent> module is	132	C<log>, is aliased to C<AnyEvent::log> and C<AE::log> when the C<AnyEvent>
67	loaded.	133	module is loaded.
68		134
69	=over 4	135	=over 4
70		136
71	=cut	137	=cut
72		138
73	package AnyEvent::Log;	139	package AnyEvent::Log;
74		140
75	use Carp ();	141	use Carp ();
76	use POSIX ();	142	use POSIX ();
77		143
		144	# layout of a context
		145	# 0 1 2 3 4, 5
		146	# [$title, $level, %$slaves, &$logcb, &$fmtcb, $cap]
		147
78	use AnyEvent (); BEGIN { AnyEvent::common_sense }	148	use AnyEvent (); BEGIN { AnyEvent::common_sense }
79	use AnyEvent::Util ();	149	#use AnyEvent::Util (); need to load this in a delayed fashion, as it uses AE::log
		150
		151	our $VERSION = $AnyEvent::VERSION;
		152
		153	our ($COLLECT, $FILTER, $LOG);
80		154
81	our ($now_int, $now_str1, $now_str2);	155	our ($now_int, $now_str1, $now_str2);
82		156
83	# Format Time, not public - yet?	157	# Format Time, not public - yet?
84	sub ft($) {	158	sub format_time($) {
85	my $i = int $_[0];	159	my $i = int $_[0];
86	my $f = sprintf "%06d", 1e6 * ($_[0] - $i);	160	my $f = sprintf "%06d", 1e6 * ($_[0] - $i);
87		161
88	($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)
89	if $now_int != $i;	163	if $now_int != $i;
90		164
91	"$now_str1$f$now_str2"	165	"$now_str1$f$now_str2"
92	}	166	}
93		167
94	our %CTX; # all logging contexts	168	our %CTX; # all package contexts
95		169
96	# creates a default package context object for the given package	170	# creates a default package context object for the given package
97	sub _pkg_ctx($) {	171	sub _pkg_ctx($) {
98	my $ctx = bless [$_[0], (1 << 10) - 1 - 1, {}], "AnyEvent::Log::Ctx";	172	my $ctx = bless [$_[0], (1 << 10) - 1 - 1, {}], "AnyEvent::Log::Ctx";
99		173
100	# link "parent" package	174	# link "parent" package
101	my $pkg = $_[0] =~ /^(.+)::/ ? $1 : "AE::Log::Top";	175	my $parent = $_[0] =~ /^(.+)::/
		176	? $CTX{$1} ||= &_pkg_ctx ("$1")
		177	: $COLLECT;
102		178
103	$pkg = $CTX{$pkg} ||= &_pkg_ctx ($pkg);
104	$ctx->[2]{$pkg+0} = $pkg;	179	$ctx->[2]{$parent+0} = $parent;
105		180
106	$ctx	181	$ctx
107	}	182	}
108		183
109	=item AnyEvent::Log::log $level, $msg[, @args]	184	=item AnyEvent::Log::log $level, $msg[, @args]
110		185
111	Requests logging of the given C<$msg> with the given log level (1..9).	186	Requests logging of the given C<$msg> with the given log level, and
112	You can also use the following strings as log level: C<fatal> (1),	187	returns true if the message was logged I<somewhere>.
113	C<alert> (2), C<critical> (3), C<error> (4), C<warn> (5), C<note> (6),
114	C<info> (7), C<debug> (8), C<trace> (9).
115		188
116	For C<fatal> log levels, the program will abort.	189	For loglevel C<fatal>, the program will abort.
117		190
118	If only a C<$msg> is given, it is logged as-is. With extra C<@args>, the	191	If only a C<$msg> is given, it is logged as-is. With extra C<@args>, the
119	C<$msg> is interpreted as an sprintf format string.	192	C<$msg> is interpreted as an sprintf format string.
120		193
121	The C<$msg> should not end with C<\n>, but may if that is convenient for	194	The C<$msg> should not end with C<\n>, but may if that is convenient for
…		…
124	Last not least, C<$msg> might be a code reference, in which case it is	197	Last not least, C<$msg> might be a code reference, in which case it is
125	supposed to return the message. It will be called only then the message	198	supposed to return the message. It will be called only then the message
126	actually gets logged, which is useful if it is costly to create the	199	actually gets logged, which is useful if it is costly to create the
127	message in the first place.	200	message in the first place.
128		201
		202	This function takes care of saving and restoring C<$!> and C<$@>, so you
		203	don't have to.
		204
129	Whether the given message will be logged depends on the maximum log level	205	Whether the given message will be logged depends on the maximum log level
130	and the caller's package.	206	and the caller's package. The return value can be used to ensure that
		207	messages or not "lost" - for example, when L<AnyEvent::Debug> detects a
		208	runtime error it tries to log it at C<die> level, but if that message is
		209	lost it simply uses warn.
131		210
132	Note that you can (and should) call this function as C<AnyEvent::log> or	211	Note that you can (and should) call this function as C<AnyEvent::log> or
133	C<AE::log>, without C<use>-ing this module if possible (i.e. you don't	212	C<AE::log>, without C<use>-ing this module if possible (i.e. you don't
134	need any additional functionality), as those functions will load the	213	need any additional functionality), as those functions will load the
135	logging module on demand only. They are also much shorter to write.	214	logging module on demand only. They are also much shorter to write.
…		…
152		231
153	=cut	232	=cut
154		233
155	# also allow syslog equivalent names	234	# also allow syslog equivalent names
156	our %STR2LEVEL = (	235	our %STR2LEVEL = (
157	fatal => 1, emerg => 1,	236	fatal => 1, emerg => 1, exit => 1,
158	alert => 2,	237	alert => 2,
159	critical => 3, crit => 3,	238	critical => 3, crit => 3,
160	error => 4, err => 4,	239	error => 4, err => 4, die => 4,
161	warn => 5, warning => 5,	240	warn => 5, warning => 5,
162	note => 6, notice => 6,	241	note => 6, notice => 6,
163	info => 7,	242	info => 7,
164	debug => 8,	243	debug => 8,
165	trace => 9,	244	trace => 9,
166	);	245	);
167		246
168	sub now () { time }	247	our $TIME_EXACT;
		248
		249	sub exact_time($) {
		250	$TIME_EXACT = shift;
		251	*_ts = $AnyEvent::MODEL
		252	? $TIME_EXACT ? \&AE::now : \&AE::time
		253	: sub () { $TIME_EXACT ? do { require Time::HiRes; Time::HiRes::time () } : time };
		254	}
		255
		256	BEGIN {
		257	exact_time 0;
		258	}
169		259
170	AnyEvent::post_detect {	260	AnyEvent::post_detect {
171	*now = \&AE::now;	261	exact_time $TIME_EXACT;
172	};	262	};
173		263
174	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);
175		265
176	# time, ctx, level, msg	266	# time, ctx, level, msg
177	sub _format($$$$) {	267	sub default_format($$$$) {
178	my $ts = ft $_[0];	268	my $ts = format_time $_[0];
179	my $ct = " ";	269	my $ct = " ";
180		270
181	my @res;	271	my @res;
182		272
183	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]) {
…		…
186	}	276	}
187		277
188	join "", @res	278	join "", @res
189	}	279	}
190		280
		281	sub fatal_exit() {
		282	exit 1;
		283	}
		284
191	sub _log {	285	sub _log {
192	my ($ctx, $level, $format, @args) = @_;	286	my ($ctx, $level, $format, @args) = @_;
193		287
194	$level = $level > 0 && $level <= 9	288	$level = $level > 0 && $level <= 9
195	? $level+0	289	? $level+0
196	: $STR2LEVEL{$level} || Carp::croak "$level: not a valid logging level, caught";	290	: $STR2LEVEL{$level} || Carp::croak "$level: not a valid logging level, caught";
197		291
198	my $mask = 1 << $level;	292	my $mask = 1 << $level;
199		293
200	my (%seen, @ctx, $now, $fmt);	294	my ($success, %seen, @ctx, $now, @fmt);
201		295
202	do	296	do
203	{	297	{
204	# skip if masked	298	# if !ref, then it's a level number
		299	if (!ref $ctx) {
		300	$level = $ctx;
205	if ($ctx->[1] & $mask && !$seen{$ctx+0}++) {	301	} elsif ($ctx->[1] & $mask and !$seen{$ctx+0}++) {
		302	# logging/recursing into this context
		303
		304	# level cap
		305	if ($ctx->[5] > $level) {
		306	push @ctx, $level; # restore level when going up in tree
		307	$level = $ctx->[5];
		308	}
		309
		310	# log if log cb
206	if ($ctx->[3]) {	311	if ($ctx->[3]) {
207	# logging target found	312	# logging target found
		313
		314	local ($!, $@);
208		315
209	# now get raw message, unless we have it already	316	# now get raw message, unless we have it already
210	unless ($now) {	317	unless ($now) {
211	$format = $format->() if ref $format;	318	$format = $format->() if ref $format;
212	$format = sprintf $format, @args if @args;	319	$format = sprintf $format, @args if @args;
213	$format =~ s/\n$//;	320	$format =~ s/\n$//;
214	$now = AE::now;	321	$now = _ts;
215	};	322	};
216		323
217	# format msg	324	# format msg
218	my $str = $ctx->[4]	325	my $str = $ctx->[4]
219	? $ctx->[4]($now, $_[0], $level, $format)	326	? $ctx->[4]($now, $_[0], $level, $format)
220	: $fmt ||= _format $now, $_[0], $level, $format;	327	: ($fmt[$level] ||= default_format $now, $_[0], $level, $format);
221		328
		329	$success = 1;
		330
222	$ctx->[3]($str);	331	$ctx->[3]($str)
		332	or push @ctx, values %{ $ctx->[2] }; # not consumed - propagate
		333	} else {
		334	push @ctx, values %{ $ctx->[2] }; # not masked - propagate
223	}	335	}
224
225	# not masked, not consumed - propagate to parent contexts
226	push @ctx, values %{ $ctx->[2] };
227	}	336	}
228	}	337	}
229	while $ctx = pop @ctx;	338	while $ctx = pop @ctx;
230		339
231	exit 1 if $level <= 1;	340	fatal_exit if $level <= 1;
		341
		342	$success
232	}	343	}
233		344
234	sub log($$;@) {	345	sub log($$;@) {
235	_log	346	_log
236	$CTX{ (caller)[0] } ||= _pkg_ctx +(caller)[0],	347	$CTX{ (caller)[0] } ||= _pkg_ctx +(caller)[0],
237	@_;	348	@_;
238	}	349	}
239		350
240	*AnyEvent::log = *AE::log = \&log;
241
242	=item $logger = AnyEvent::Log::logger $level[, \$enabled]	351	=item $logger = AnyEvent::Log::logger $level[, \$enabled]
243		352
244	Creates a code reference that, when called, acts as if the	353	Creates a code reference that, when called, acts as if the
245	C<AnyEvent::Log::log> function was called at this point with the givne	354	C<AnyEvent::Log::log> function was called at this point with the given
246	level. C<$logger> is passed a C<$msg> and optional C<@args>, just as with	355	level. C<$logger> is passed a C<$msg> and optional C<@args>, just as with
247	the C<AnyEvent::Log::log> function:	356	the C<AnyEvent::Log::log> function:
248		357
249	my $debug_log = AnyEvent::Log::logger "debug";	358	my $debug_log = AnyEvent::Log::logger "debug";
250		359
…		…
275	# and later in your program	384	# and later in your program
276	$debug_log->("yo, stuff here") if $debug;	385	$debug_log->("yo, stuff here") if $debug;
277		386
278	$debug and $debug_log->("123");	387	$debug and $debug_log->("123");
279		388
280	Note: currently the enabled var is always true - that will be fixed in a
281	future version :)
282
283	=cut	389	=cut
284		390
285	our %LOGGER;	391	our %LOGGER;
286		392
287	# re-assess logging status for all loggers	393	# re-assess logging status for all loggers
288	sub _reassess {	394	sub _reassess {
		395	local $SIG{__DIE__};
		396	my $die = sub { die };
		397
289	for (@_ ? $LOGGER{$_[0]} : values %LOGGER) {	398	for (@_ ? $LOGGER{$_[0]} : values %LOGGER) {
290	my ($ctx, $level, $renabled) = @$_;	399	my ($ctx, $level, $renabled) = @$_;
291		400
292	# to detect whether a message would be logged, we # actually	401	# to detect whether a message would be logged, we actually
293	# try to log one and die. this isn't fast, but we can be	402	# try to log one and die. this isn't fast, but we can be
294	# sure that the logging decision is correct :)	403	# sure that the logging decision is correct :)
295		404
296	$$renabled = !eval {	405	$$renabled = !eval {
297	local $SIG{__DIE__};
298
299	_log $ctx, $level, sub { die };	406	_log $ctx, $level, $die;
300		407
301	1	408	1
302	};	409	};
303
304	$$renabled = 1; # TODO
305	}	410	}
306	}	411	}
307		412
308	sub _logger($;$) {	413	sub _logger {
309	my ($ctx, $level, $renabled) = @_;	414	my ($ctx, $level, $renabled) = @_;
310		415
311	$renabled ||= \my $enabled;
312
313	$$renabled = 1;	416	$$renabled = 1;
314		417
315	my $logger = [$ctx, $level, $renabled];	418	my $logger = [$ctx, $level, $renabled];
316		419
317	$LOGGER{$logger+0} = $logger;	420	$LOGGER{$logger+0} = $logger;
318		421
319	_reassess $logger+0;	422	_reassess $logger+0;
320		423
		424	require AnyEvent::Util unless $AnyEvent::Util::VERSION;
321	my $guard = AnyEvent::Util::guard {	425	my $guard = AnyEvent::Util::guard (sub {
322	# "clean up"	426	# "clean up"
323	delete $LOGGER{$logger+0};	427	delete $LOGGER{$logger+0};
324	};	428	});
325		429
326	sub {	430	sub {
327	$guard if 0; # keep guard alive, but don't cause runtime overhead	431	$guard if 0; # keep guard alive, but don't cause runtime overhead
328		432
329	_log $ctx, $level, @_	433	_log $ctx, $level, @_
…		…
334	sub logger($;$) {	438	sub logger($;$) {
335	_logger	439	_logger
336	$CTX{ (caller)[0] } ||= _pkg_ctx +(caller)[0],	440	$CTX{ (caller)[0] } ||= _pkg_ctx +(caller)[0],
337	@_	441	@_
338	}	442	}
		443
		444	=item AnyEvent::Log::exact_time $on
		445
		446	By default, C<AnyEvent::Log> will use C<AE::now>, i.e. the cached
		447	eventloop time, for the log timestamps. After calling this function with a
		448	true value it will instead resort to C<AE::time>, i.e. fetch the current
		449	time on each log message. This only makes a difference for event loops
		450	that actually cache the time (such as L<EV> or L<AnyEvent::Loop>).
		451
		452	This setting can be changed at any time by calling this function.
		453
		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
		456	C<Time::HiRes::time> when logging a message before L<AnyEvent> becomes
		457	available.
		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.
339		493
340	=back	494	=back
341		495
342	=head1 LOGGING CONTEXTS	496	=head1 LOGGING CONTEXTS
343		497
…		…
356	timestamp, context, level and string message and formats it in the way	510	timestamp, context, level and string message and formats it in the way
357	it should be logged) and a logging callback (which is responsible for	511	it should be logged) and a logging callback (which is responsible for
358	actually logging the formatted message and telling C<AnyEvent::Log>	512	actually logging the formatted message and telling C<AnyEvent::Log>
359	whether it has consumed the message, or whether it should be propagated).	513	whether it has consumed the message, or whether it should be propagated).
360		514
361	For propagation, a context can have any number of attached I<parent	515	For propagation, a context can have any number of attached I<slave
362	contexts>. Any message that is neither masked by the logging mask nor	516	contexts>. Any message that is neither masked by the logging mask nor
363	masked by the logging callback returning true will be passed to all parent	517	masked by the logging callback returning true will be passed to all slave
364	contexts.	518	contexts.
365		519
366	Each call to a logging function will log the message at most once per	520	Each call to a logging function will log the message at most once per
367	context, so it does not matter (much) if there are cycles or if the	521	context, so it does not matter (much) if there are cycles or if the
368	message can arrive at the same context via multiple paths.	522	message can arrive at the same context via multiple paths.
…		…
372	By default, all logging contexts have an full set of log levels ("all"), a	526	By default, all logging contexts have an full set of log levels ("all"), a
373	disabled logging callback and the default formatting callback.	527	disabled logging callback and the default formatting callback.
374		528
375	Package contexts have the package name as logging title by default.	529	Package contexts have the package name as logging title by default.
376		530
377	They have exactly one parent - the context of the "parent" package. The	531	They have exactly one slave - the context of the "parent" package. The
378	parent package is simply defined to be the package name without the last	532	parent package is simply defined to be the package name without the last
379	component, i.e. C<AnyEvent::Debug::Wrapped> becomes C<AnyEvent::Debug>,	533	component, i.e. C<AnyEvent::Debug::Wrapped> becomes C<AnyEvent::Debug>,
380	and C<AnyEvent> becomes ... C<AnyEvent::Log::Top> which is the	534	and C<AnyEvent> becomes ... C<$AnyEvent::Log::COLLECT> which is the
381	exception of the rule - just like the parent of any package name in	535	exception of the rule - just like the "parent" of any single-component
382	Perl is C<main>, the default parent of any top-level package context is	536	package name in Perl is C<main>, the default slave of any top-level
383	C<AnyEvent::Log::Top>.	537	package context is C<$AnyEvent::Log::COLLECT>.
384		538
385	Since perl packages form only an approximate hierarchy, this parent	539	Since perl packages form only an approximate hierarchy, this slave
386	context can of course be removed.	540	context can of course be removed.
387		541
388	All other (anonymous) contexts have no parents and an empty title by	542	All other (anonymous) contexts have no slaves and an empty title by
389	default.	543	default.
390		544
391	When the module is loaded it creates the default context called	545	When the module is loaded it creates the C<$AnyEvent::Log::LOG> logging
392	C<AnyEvent::Log::Default> (also stored in C<$AnyEvent::Log::Default>),	546	context that simply logs everything via C<warn>, without propagating
393	which simply logs everything to STDERR and doesn't propagate anything
394	anywhere by default. The purpose of the default context is to provide	547	anything anywhere by default. The purpose of this context is to provide
395	a convenient place to override the global logging target or to attach	548	a convenient place to override the global logging target or to attach
396	additional log targets. It's not meant for filtering.	549	additional log targets. It's not meant for filtering.
397		550
398	It then creates the root context called C<AnyEvent::Log::Root> (also	551	It then creates the C<$AnyEvent::Log::FILTER> context whose
399	stored in C<$AnyEvent::Log::Root>) and sets its log level set to all	552	purpose is to suppress all messages with priority higher
400	levels up to the one specified by C<$ENV{PERL_ANYEVENT_VERBOSE}>. It	553	than C<$ENV{PERL_ANYEVENT_VERBOSE}>. It then attached the
401	then attached the default logging context to it. The purpose of the root	554	C<$AnyEvent::Log::LOG> context to it. The purpose of the filter context
402	context is to simply provide filtering according to some global log level.	555	is to simply provide filtering according to some global log level.
403		556
404	Finally it creates the top-level package context called	557	Finally it creates the top-level package context C<$AnyEvent::Log::COLLECT>
405	C<AnyEvent::Log::Top> (also stored in, you might have guessed,	558	and attaches the C<$AnyEvent::Log::FILTER> context to it, but otherwise
406	C<$AnyEvent::Log::Top>) and attached the root context but otherwise leaves
407	it at default config. It's purpose is simply to collect all log messages	559	leaves it at default config. Its purpose is simply to collect all log
408	system-wide.	560	messages system-wide.
409		561
410	These three special contexts can also be referred to by the	562	The hierarchy is then:
411	package/context names C<AE::Log::Default>, C<AE::Log::Root> and
412	C<AE::Log::Top>.
413		563
		564	any package, eventually -> $COLLECT -> $FILTER -> $LOG
		565
414	The effect of all this is that log messages, by default, wander up	566	The effect of all this is that log messages, by default, wander up to the
415	to the root context where log messages with lower priority then	567	C<$AnyEvent::Log::COLLECT> context where all messages normally end up,
		568	from there to C<$AnyEvent::Log::FILTER> where log messages with lower
416	C<$ENV{PERL_ANYEVENT_VERBOSE}> will be filtered away and then to the	569	priority then C<$ENV{PERL_ANYEVENT_VERBOSE}> will be filtered out and then
417	AnyEvent::Log::Default context to be logged to STDERR.	570	to the C<$AnyEvent::Log::LOG> context to be passed to C<warn>.
418		571
419	Splitting the top level context into three contexts makes it easy to set	572	This makes it easy to set a global logging level (by modifying $FILTER),
420	a global logging level (by modifying the root context), but still allow	573	but still allow other contexts to send, for example, their debug and trace
421	other contexts to log, for example, their debug and trace messages to the
422	default target despite the global logging level, or to attach additional	574	messages to the $LOG target despite the global logging level, or to attach
423	log targets that log messages, regardless of the global logging level.	575	additional log targets that log messages, regardless of the global logging
		576	level.
424		577
425	It also makes it easy to replace the default STDERR-logger by something	578	It also makes it easy to modify the default warn-logger ($LOG) to
426	that logs to a file, or to attach additional logging targets.	579	something that logs to a file, or to attach additional logging targets
		580	(such as loggign to a file) by attaching it to $FILTER.
427		581
428	=head2 CREATING/FINDING/DESTROYING CONTEXTS	582	=head2 CREATING/FINDING/DESTROYING CONTEXTS
429		583
430	=over 4	584	=over 4
431		585
…		…
453	: bless [undef, (1 << 10) - 1 - 1], "AnyEvent::Log::Ctx"	607	: bless [undef, (1 << 10) - 1 - 1], "AnyEvent::Log::Ctx"
454	}	608	}
455		609
456	=item AnyEvent::Log::reset	610	=item AnyEvent::Log::reset
457		611
458	Deletes all contexts and recreates the default hierarchy, i.e. resets the	612	Resets all package contexts and recreates the default hierarchy if
459	logging subsystem to defaults.	613	necessary, i.e. resets the logging subsystem to defaults, as much as
		614	possible. This process keeps references to contexts held by other parts of
		615	the program intact.
460		616
461	This can be used to implement config-file (re-)loading: before loading a	617	This can be used to implement config-file (re-)loading: before loading a
462	configuration, reset all contexts.	618	configuration, reset all contexts.
463		619
464	=cut	620	=cut
465		621
		622	our $ORIG_VERBOSE = $AnyEvent::VERBOSE;
		623	$AnyEvent::VERBOSE = 9;
		624
466	sub reset {	625	sub reset {
467	@$_ = () for values %CTX; # just to be sure - to kill circular logging dependencies	626	# hard to kill complex data structures
468	%CTX = ();	627	# we "recreate" all package loggers and reset the hierarchy
		628	while (my ($k, $v) = each %CTX) {
		629	@$v = ($k, (1 << 10) - 1 - 1, { });
469		630
470	my $default = ctx undef;	631	$v->attach ($k =~ /^(.+)::/ ? $CTX{$1} : $AnyEvent::Log::COLLECT);
471	$default->title ("AnyEvent::Log::Default");
472	$default->log_cb (sub {
473	print STDERR shift;
474	0
475	});	632	}
476	$AnyEvent::Log::Default = $CTX{"AnyEvent::Log::Default"} = $CTX{"AE::Log::Default"} = $default;
477		633
478	my $root = ctx undef;	634	@$_ = ($_->[0], (1 << 10) - 1 - 1)
479	$root->title ("AnyEvent::Log::Root");	635	for $LOG, $FILTER, $COLLECT;
480	$root->level ($AnyEvent::VERBOSE);
481	$root->attach ($default);
482	$AnyEvent::Log::Root = $CTX{"AnyEvent::Log::Root"} = $CTX{"AE::Log::Root"} = $root;
483		636
484	my $top = ctx undef;	637	#$LOG->slaves;
485	$top->title ("AnyEvent::Log::Top");	638	$LOG->title ('$AnyEvent::Log::LOG');
486	$top->attach ($root);	639	$LOG->log_to_warn;
487	$AnyEvent::Log::Top = $CTX{"AnyEvent::Log::Top"} = $CTX{"AE::Log::Top"} = $top;	640
		641	$FILTER->slaves ($LOG);
		642	$FILTER->title ('$AnyEvent::Log::FILTER');
		643	$FILTER->level ($ORIG_VERBOSE);
		644
		645	$COLLECT->slaves ($FILTER);
		646	$COLLECT->title ('$AnyEvent::Log::COLLECT');
		647
		648	_reassess;
488	}	649	}
		650
		651	# override AE::log/logger
		652	*AnyEvent::log = *AE::log = \&log;
		653	*AnyEvent::logger = *AE::logger = \&logger;
		654
		655	# convert AnyEvent loggers to AnyEvent::Log loggers
		656	$_->[0] = ctx $_->[0] # convert "pkg" to "ctx"
		657	for values %LOGGER;
		658
		659	# create the default logger contexts
		660	$LOG = ctx undef;
		661	$FILTER = ctx undef;
		662	$COLLECT = ctx undef;
489		663
490	AnyEvent::Log::reset;	664	AnyEvent::Log::reset;
491		665
492	# hello, CPAN, please catch me	666	# hello, CPAN, please catch me
493	package AnyEvent::Log::Default;
494	package AE::Log::Default;
495	package AnyEvent::Log::Root;
496	package AE::Log::Root;
497	package AnyEvent::Log::Top;	667	package AnyEvent::Log::LOG;
498	package AE::Log::Top;	668	package AE::Log::LOG;
		669	package AnyEvent::Log::FILTER;
		670	package AE::Log::FILTER;
		671	package AnyEvent::Log::COLLECT;
		672	package AE::Log::COLLECT;
499		673
500	package AnyEvent::Log::Ctx;	674	package AnyEvent::Log::Ctx;
501
502	# 0 1 2 3 4
503	# [$title, $level, %$parents, &$logcb, &$fmtcb]
504		675
505	=item $ctx = new AnyEvent::Log::Ctx methodname => param...	676	=item $ctx = new AnyEvent::Log::Ctx methodname => param...
506		677
507	This is a convenience constructor that makes it simpler to construct	678	This is a convenience constructor that makes it simpler to construct
508	anonymous logging contexts.	679	anonymous logging contexts.
…		…
511	name as the key with the value as parameter, unless the value is an	682	name as the key with the value as parameter, unless the value is an
512	arrayref, in which case it calls the method with the contents of the	683	arrayref, in which case it calls the method with the contents of the
513	array. The methods are called in the same order as specified.	684	array. The methods are called in the same order as specified.
514		685
515	Example: create a new logging context and set both the default logging	686	Example: create a new logging context and set both the default logging
516	level, some parent contexts and a logging callback.	687	level, some slave contexts and a logging callback.
517		688
518	$ctx = new AnyEvent::Log::Ctx	689	$ctx = new AnyEvent::Log::Ctx
519	title => "dubious messages",	690	title => "dubious messages",
520	level => "error",	691	level => "error",
521	log_cb => sub { print STDOUT shift; 0 },	692	log_cb => sub { print STDOUT shift; 0 },
522	parents => [$ctx1, $ctx, $ctx2],	693	slaves => [$ctx1, $ctx, $ctx2],
523	;	694	;
524		695
525	=back	696	=back
526		697
527	=cut	698	=cut
…		…
595	Enables logging for the given levels, leaving all others unchanged.	766	Enables logging for the given levels, leaving all others unchanged.
596		767
597	=item $ctx->disable ($level[, $level...])	768	=item $ctx->disable ($level[, $level...])
598		769
599	Disables logging for the given levels, leaving all others unchanged.	770	Disables logging for the given levels, leaving all others unchanged.
		771
		772	=item $ctx->cap ($level)
		773
		774	Caps the maximum priority to the given level, for all messages logged
		775	to, or passing through, this context. That is, while this doesn't affect
		776	whether a message is logged or passed on, the maximum priority of messages
		777	will be limited to the specified level - messages with a higher priority
		778	will be set to the specified priority.
		779
		780	Another way to view this is that C<< ->level >> filters out messages with
		781	a too low priority, while C<< ->cap >> modifies messages with a too high
		782	priority.
		783
		784	This is useful when different log targets have different interpretations
		785	of priority. For example, for a specific command line program, a wrong
		786	command line switch might well result in a C<fatal> log message, while the
		787	same message, logged to syslog, is likely I<not> fatal to the system or
		788	syslog facility as a whole, but more likely a mere C<error>.
		789
		790	This can be modeled by having a stderr logger that logs messages "as-is"
		791	and a syslog logger that logs messages with a level cap of, say, C<error>,
		792	or, for truly system-critical components, actually C<critical>.
600		793
601	=cut	794	=cut
602		795
603	sub _lvl_lst {	796	sub _lvl_lst {
604	map {	797	map {
…		…
606	: $_ eq "all" ? (1 .. 9)	799	: $_ eq "all" ? (1 .. 9)
607	: $STR2LEVEL{$_} || Carp::croak "$_: not a valid logging level, caught"	800	: $STR2LEVEL{$_} || Carp::croak "$_: not a valid logging level, caught"
608	} @_	801	} @_
609	}	802	}
610		803
		804	sub _lvl {
		805	$_[0] =~ /^(?:0|off|none)$/ ? 0 : (_lvl_lst $_[0])[-1]
		806	}
		807
611	our $NOP_CB = sub { 0 };	808	our $NOP_CB = sub { 0 };
612		809
613	sub levels {	810	sub levels {
614	my $ctx = shift;	811	my $ctx = shift;
615	$ctx->[1] = 0;	812	$ctx->[1] = 0;
…		…
618	AnyEvent::Log::_reassess;	815	AnyEvent::Log::_reassess;
619	}	816	}
620		817
621	sub level {	818	sub level {
622	my $ctx = shift;	819	my $ctx = shift;
623	my $lvl = $_[0] =~ /^(?:0|off|none)$/ ? 0 : (_lvl_lst $_[0])[-1];
624
625	$ctx->[1] = ((1 << $lvl) - 1) << 1;	820	$ctx->[1] = ((1 << &_lvl) - 1) << 1;
626	AnyEvent::Log::_reassess;	821	AnyEvent::Log::_reassess;
627	}	822	}
628		823
629	sub enable {	824	sub enable {
630	my $ctx = shift;	825	my $ctx = shift;
…		…
638	$ctx->[1] &= ~(1 << $_)	833	$ctx->[1] &= ~(1 << $_)
639	for &_lvl_lst;	834	for &_lvl_lst;
640	AnyEvent::Log::_reassess;	835	AnyEvent::Log::_reassess;
641	}	836	}
642		837
		838	sub cap {
		839	my $ctx = shift;
		840	$ctx->[5] = &_lvl;
		841	}
		842
643	=back	843	=back
644		844
645	=head3 PARENT CONTEXTS	845	=head3 SLAVE CONTEXTS
646		846
647	The following methods attach and detach another logging context to a	847	The following methods attach and detach another logging context to a
648	logging context.	848	logging context.
649		849
650	Log messages are propagated to all parent contexts, unless the logging	850	Log messages are propagated to all slave contexts, unless the logging
651	callback consumes the message.	851	callback consumes the message.
652		852
653	=over 4	853	=over 4
654		854
655	=item $ctx->attach ($ctx2[, $ctx3...])	855	=item $ctx->attach ($ctx2[, $ctx3...])
656		856
657	Attaches the given contexts as parents to this context. It is not an error	857	Attaches the given contexts as slaves to this context. It is not an error
658	to add a context twice (the second add will be ignored).	858	to add a context twice (the second add will be ignored).
659		859
660	A context can be specified either as package name or as a context object.	860	A context can be specified either as package name or as a context object.
661		861
662	=item $ctx->detach ($ctx2[, $ctx3...])	862	=item $ctx->detach ($ctx2[, $ctx3...])
663		863
664	Removes the given parents from this context - it's not an error to attempt	864	Removes the given slaves from this context - it's not an error to attempt
665	to remove a context that hasn't been added.	865	to remove a context that hasn't been added.
666		866
667	A context can be specified either as package name or as a context object.	867	A context can be specified either as package name or as a context object.
668		868
669	=item $ctx->parents ($ctx2[, $ctx3...])	869	=item $ctx->slaves ($ctx2[, $ctx3...])
670		870
671	Replaces all parents attached to this context by the ones given.	871	Replaces all slaves attached to this context by the ones given.
672		872
673	=cut	873	=cut
674		874
675	sub attach {	875	sub attach {
676	my $ctx = shift;	876	my $ctx = shift;
…		…
684		884
685	delete $ctx->[2]{$_+0}	885	delete $ctx->[2]{$_+0}
686	for map { AnyEvent::Log::ctx $_ } @_;	886	for map { AnyEvent::Log::ctx $_ } @_;
687	}	887	}
688		888
689	sub parents {	889	sub slaves {
690	undef $_[0][2];	890	undef $_[0][2];
691	&attach;	891	&attach;
692	}	892	}
693		893
694	=back	894	=back
695		895
696	=head3 MESSAGE LOGGING	896	=head3 LOG TARGETS
697		897
698	The following methods configure how the logging context actually does	898	The following methods configure how the logging context actually does
699	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
700	whatever it wants to do with it) and also allows you to log messages	900	whatever it wants to do with it).
701	directly to a context, without going via your package context.
702		901
703	=over 4	902	=over 4
704		903
705	=item $ctx->log_cb ($cb->($str))	904	=item $ctx->log_cb ($cb->($str))
706		905
…		…
711	(see C<fmt_cb> below) - normally simple text strings that end with a	910	(see C<fmt_cb> below) - normally simple text strings that end with a
712	newline (and are possibly multiline themselves).	911	newline (and are possibly multiline themselves).
713		912
714	It also has to return true iff it has consumed the log message, and false	913	It also has to return true iff it has consumed the log message, and false
715	if it hasn't. Consuming a message means that it will not be sent to any	914	if it hasn't. Consuming a message means that it will not be sent to any
716	parent context. When in doubt, return C<0> from your logging callback.	915	slave context. When in doubt, return C<0> from your logging callback.
717		916
718	Example: a very simple logging callback, simply dump the message to STDOUT	917	Example: a very simple logging callback, simply dump the message to STDOUT
719	and do not consume it.	918	and do not consume it.
720		919
721	$ctx->log_cb (sub { print STDERR shift; 0 });	920	$ctx->log_cb (sub { print STDERR shift; 0 });
…		…
729	your program.	928	your program.
730		929
731	$ctx->levels ("debug", "trace");	930	$ctx->levels ("debug", "trace");
732	$ctx->log_cb (sub { 1 }); # do not log, but eat debug and trace messages	931	$ctx->log_cb (sub { 1 }); # do not log, but eat debug and trace messages
733		932
734	=item $ctx->fmt_cb ($fmt_cb->($timestamp, $ctx, $level, $message))	933	=item $ctx->fmt_cb ($fmt_cb->($timestamp, $orig_ctx, $level, $message))
735		934
736	Replaces the formatting callback on the context (C<undef> restores the	935	Replaces the formatting callback on the context (C<undef> restores the
737	default formatter).	936	default formatter).
738		937
739	The callback is passed the (possibly fractional) timestamp, the original	938	The callback is passed the (possibly fractional) timestamp, the original
740	logging context, the (numeric) logging level and the raw message string and needs to	939	logging context (object, not title), the (numeric) logging level and
741	return a formatted log message. In most cases this will be a string, but	940	the raw message string and needs to return a formatted log message. In
742	it could just as well be an array reference that just stores the values.	941	most cases this will be a string, but it could just as well be an array
		942	reference that just stores the values.
		943
		944	If, for some reason, you want to use C<caller> to find out more about the
		945	logger then you should walk up the call stack until you are no longer
		946	inside the C<AnyEvent::Log> package.
		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	});
743		961
744	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
745	brackets.	963	brackets.
746		964
747	$ctx->fmt_cb (sub {	965	$ctx->fmt_cb (sub {
…		…
749		967
750	"<$lvl>$msg\n"	968	"<$lvl>$msg\n"
751	});	969	});
752		970
753	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
754	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.
755		973
756	$ctx->fmt_cb (sub { \@_ });	974	$ctx->fmt_cb (sub { \@_ });
757	$ctx->log_cb (sub {	975	$ctx->log_cb (sub {
758	my ($msg) = @_;	976	my ($msg) = @_;
759		977
…		…
764	"$msg->[3]";	982	"$msg->[3]";
765		983
766	0	984	0
767	});	985	});
768		986
		987	=item $ctx->log_to_warn
		988
		989	Sets the C<log_cb> to simply use C<CORE::warn> to report any messages
		990	(usually this logs to STDERR).
		991
		992	=item $ctx->log_to_file ($path)
		993
		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.
		996
		997	=item $ctx->log_to_path ($path)
		998
		999	Same as C<< ->log_to_file >>, but opens the file for each message. This
		1000	is much slower, but allows you to change/move/rename/delete the file at
		1001	basically any time.
		1002
		1003	Needless(?) to say, if you do not want to be bitten by some evil person
		1004	calling C<chdir>, the path should be absolute. Doesn't help with
		1005	C<chroot>, but hey...
		1006
		1007	=item $ctx->log_to_syslog ([$facility])
		1008
		1009	Logs all messages via L<Sys::Syslog>, mapping C<trace> to C<debug> and
		1010	all the others in the obvious way. If specified, then the C<$facility> is
		1011	used as the facility (C<user>, C<auth>, C<local0> and so on). The default
		1012	facility is C<user>.
		1013
		1014	Note that this function also sets a C<fmt_cb> - the logging part requires
		1015	an array reference with [$level, $str] as input.
		1016
769	=cut	1017	=cut
770		1018
771	sub log_cb {	1019	sub log_cb {
772	my ($ctx, $cb) = @_;	1020	my ($ctx, $cb) = @_;
773		1021
…		…
778	my ($ctx, $cb) = @_;	1026	my ($ctx, $cb) = @_;
779		1027
780	$ctx->[4] = $cb;	1028	$ctx->[4] = $cb;
781	}	1029	}
782		1030
		1031	sub log_to_warn {
		1032	my ($ctx, $path) = @_;
		1033
		1034	$ctx->log_cb (sub {
		1035	warn shift;
		1036	0
		1037	});
		1038	}
		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
		1124	sub log_to_file {
		1125	my ($ctx, $path) = @_;
		1126
		1127	_log_to_disk $ctx, $path, 1;
		1128	}
		1129
		1130	sub log_to_path {
		1131	my ($ctx, $path) = @_;
		1132
		1133	_log_to_disk $ctx, $path, 0;
		1134	}
		1135
		1136	sub log_to_syslog {
		1137	my ($ctx, $facility) = @_;
		1138
		1139	require Sys::Syslog;
		1140
		1141	$ctx->fmt_cb (sub {
		1142	my $str = $_[3];
		1143	$str =~ s/\n(?=.)/\n+ /g;
		1144
		1145	[$_[2], "($_[1][0]) $str"]
		1146	});
		1147
		1148	$facility ||= "user";
		1149
		1150	$ctx->log_cb (sub {
		1151	my $lvl = $_[0][0] < 9 ? $_[0][0] : 8;
		1152
		1153	Sys::Syslog::syslog ("$facility|" . ($lvl - 1), $_)
		1154	for split /\n/, $_[0][1];
		1155
		1156	0
		1157	});
		1158	}
		1159
		1160	=back
		1161
		1162	=head3 MESSAGE LOGGING
		1163
		1164	These methods allow you to log messages directly to a context, without
		1165	going via your package context.
		1166
		1167	=over 4
		1168
783	=item $ctx->log ($level, $msg[, @params])	1169	=item $ctx->log ($level, $msg[, @params])
784		1170
785	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");
786		1176
787	=item $logger = $ctx->logger ($level[, \$enabled])	1177	=item $logger = $ctx->logger ($level[, \$enabled])
788		1178
789	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
790	context.	1180	context.
…		…
792	=cut	1182	=cut
793		1183
794	*log = \&AnyEvent::Log::_log;	1184	*log = \&AnyEvent::Log::_log;
795	*logger = \&AnyEvent::Log::_logger;	1185	*logger = \&AnyEvent::Log::_logger;
796		1186
797	1;
798
799	=back	1187	=back
800		1188
		1189	=cut
		1190
		1191	package AnyEvent::Log;
		1192
		1193	=head1 CONFIGURATION VIA $ENV{PERL_ANYEVENT_LOG}
		1194
		1195	Logging can also be configured by setting the environment variable
		1196	C<PERL_ANYEVENT_LOG> (or C<AE_LOG>).
		1197
		1198	The value consists of one or more logging context specifications separated
		1199	by C<:> or whitespace. Each logging specification in turn starts with a
		1200	context name, followed by C<=>, followed by zero or more comma-separated
		1201	configuration directives, here are some examples:
		1202
		1203	# set default logging level
		1204	filter=warn
		1205
		1206	# log to file instead of to stderr
		1207	log=file=/tmp/mylog
		1208
		1209	# log to file in addition to stderr
		1210	log=+%file:%file=file=/tmp/mylog
		1211
		1212	# enable debug log messages, log warnings and above to syslog
		1213	filter=debug:log=+%warnings:%warnings=warn,syslog=LOG_LOCAL0
		1214
		1215	# log trace messages (only) from AnyEvent::Debug to file
		1216	AnyEvent::Debug=+%trace:%trace=only,trace,file=/tmp/tracelog
		1217
		1218	A context name in the log specification can be any of the following:
		1219
		1220	=over 4
		1221
		1222	=item C<collect>, C<filter>, C<log>
		1223
		1224	Correspond to the three predefined C<$AnyEvent::Log::COLLECT>,
		1225	C<AnyEvent::Log::FILTER> and C<$AnyEvent::Log::LOG> contexts.
		1226
		1227	=item C<%name>
		1228
		1229	Context names starting with a C<%> are anonymous contexts created when the
		1230	name is first mentioned. The difference to package contexts is that by
		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.
		1235
		1236	=item a perl package name
		1237
		1238	Any other string references the logging context associated with the given
		1239	Perl C<package>. In the unlikely case where you want to specify a package
		1240	context that matches on of the other context name forms, you can add a
		1241	C<::> to the package name to force interpretation as a package.
		1242
		1243	=back
		1244
		1245	The configuration specifications can be any number of the following:
		1246
		1247	=over 4
		1248
		1249	=item C<stderr>
		1250
		1251	Configures the context to use Perl's C<warn> function (which typically
		1252	logs to C<STDERR>). Works like C<log_to_warn>.
		1253
		1254	=item C<file=>I<path>
		1255
		1256	Configures the context to log to a file with the given path. Works like
		1257	C<log_to_file>.
		1258
		1259	=item C<path=>I<path>
		1260
		1261	Configures the context to log to a file with the given path. Works like
		1262	C<log_to_path>.
		1263
		1264	=item C<syslog> or C<syslog=>I<expr>
		1265
		1266	Configures the context to log to syslog. If I<expr> is given, then it is
		1267	evaluated in the L<Sys::Syslog> package, so you could use:
		1268
		1269	log=syslog=LOG_LOCAL0
		1270
		1271	=item C<nolog>
		1272
		1273	Configures the context to not log anything by itself, which is the
		1274	default. Same as C<< $ctx->log_cb (undef) >>.
		1275
		1276	=item C<cap=>I<level>
		1277
		1278	Caps logging messages entering this context at the given level, i.e.
		1279	reduces the priority of messages with higher priority than this level. The
		1280	default is C<0> (or C<off>), meaning the priority will not be touched.
		1281
		1282	=item C<0> or C<off>
		1283
		1284	Sets the logging level of the context to C<0>, i.e. all messages will be
		1285	filtered out.
		1286
		1287	=item C<all>
		1288
		1289	Enables all logging levels, i.e. filtering will effectively be switched
		1290	off (the default).
		1291
		1292	=item C<only>
		1293
		1294	Disables all logging levels, and changes the interpretation of following
		1295	level specifications to enable the specified level only.
		1296
		1297	Example: only enable debug messages for a context.
		1298
		1299	context=only,debug
		1300
		1301	=item C<except>
		1302
		1303	Enables all logging levels, and changes the interpretation of following
		1304	level specifications to disable that level. Rarely used.
		1305
		1306	Example: enable all logging levels except fatal and trace (this is rather
		1307	nonsensical).
		1308
		1309	filter=exept,fatal,trace
		1310
		1311	=item C<level>
		1312
		1313	Enables all logging levels, and changes the interpretation of following
		1314	level specifications to be "that level or any higher priority
		1315	message". This is the default.
		1316
		1317	Example: log anything at or above warn level.
		1318
		1319	filter=warn
		1320
		1321	# or, more verbose
		1322	filter=only,level,warn
		1323
		1324	=item C<1>..C<9> or a logging level name (C<error>, C<debug> etc.)
		1325
		1326	A numeric loglevel or the name of a loglevel will be interpreted according
		1327	to the most recent C<only>, C<except> or C<level> directive. By default,
		1328	specifying a logging level enables that and any higher priority messages.
		1329
		1330	=item C<+>I<context>
		1331
		1332	Attaches the named context as slave to the context.
		1333
		1334	=item C<+>
		1335
		1336	A lone C<+> detaches all contexts, i.e. clears the slave list from the
		1337	context. Anonymous (C<%name>) contexts have no attached slaves by default,
		1338	but package contexts have the parent context as slave by default.
		1339
		1340	Example: log messages from My::Module to a file, do not send them to the
		1341	default log collector.
		1342
		1343	My::Module=+,file=/tmp/mymodulelog
		1344
		1345	=back
		1346
		1347	Any character can be escaped by prefixing it with a C<\> (backslash), as
		1348	usual, so to log to a file containing a comma, colon, backslash and some
		1349	spaces in the filename, you would do this:
		1350
		1351	PERL_ANYEVENT_LOG='log=file=/some\ \:file\ with\,\ \\-escapes'
		1352
		1353	Since whitespace (which includes newlines) is allowed, it is fine to
		1354	specify multiple lines in C<PERL_ANYEVENT_LOG>, e.g.:
		1355
		1356	PERL_ANYEVENT_LOG="
		1357	filter=warn
		1358	AnyEvent::Debug=+%trace
		1359	%trace=only,trace,+log
		1360	" myprog
		1361
		1362	Also, in the unlikely case when you want to concatenate specifications,
		1363	use whitespace as separator, as C<::> will be interpreted as part of a
		1364	module name, an empty spec with two separators:
		1365
		1366	PERL_ANYEVENT_LOG="$PERL_ANYEVENT_LOG MyMod=debug"
		1367
		1368	=cut
		1369
		1370	for (my $spec = $ENV{PERL_ANYEVENT_LOG}) {
		1371	my %anon;
		1372
		1373	my $pkg = sub {
		1374	$_[0] eq "log" ? $LOG
		1375	: $_[0] eq "filter" ? $FILTER
		1376	: $_[0] eq "collect" ? $COLLECT
		1377	: $_[0] =~ /^%(.+)$/ ? ($anon{$1} ||= do { my $ctx = ctx undef; $ctx->[0] = $_[0]; $ctx })
		1378	: $_[0] =~ /^(.*?)(?:::)?$/ ? ctx "$1" # egad :/
		1379	: die # never reached?
		1380	};
		1381
		1382	/\G[[:space:]]+/gc; # skip initial whitespace
		1383
		1384	while (/\G((?:[^:=[:space:]]+|::|\\.)+)=/gc) {
		1385	my $ctx = $pkg->($1);
		1386	my $level = "level";
		1387
		1388	while (/\G((?:[^,:[:space:]]+|::|\\.)+)/gc) {
		1389	for ("$1") {
		1390	if ($_ eq "stderr" ) { $ctx->log_to_warn;
		1391	} elsif (/^file=(.+)/ ) { $ctx->log_to_file ("$1");
		1392	} elsif (/^path=(.+)/ ) { $ctx->log_to_path ("$1");
		1393	} elsif (/^syslog(?:=(.*))?/ ) { require Sys::Syslog; $ctx->log_to_syslog ("$1");
		1394	} elsif ($_ eq "nolog" ) { $ctx->log_cb (undef);
		1395	} elsif (/^cap=(.+)/ ) { $ctx->cap ("$1");
		1396	} elsif (/^\+(.+)$/ ) { $ctx->attach ($pkg->("$1"));
		1397	} elsif ($_ eq "+" ) { $ctx->slaves;
		1398	} elsif ($_ eq "off" or $_ eq "0") { $ctx->level (0);
		1399	} elsif ($_ eq "all" ) { $ctx->level ("all");
		1400	} elsif ($_ eq "level" ) { $ctx->level ("all"); $level = "level";
		1401	} elsif ($_ eq "only" ) { $ctx->level ("off"); $level = "enable";
		1402	} elsif ($_ eq "except" ) { $ctx->level ("all"); $level = "disable";
		1403	} elsif (/^\d$/ ) { $ctx->$level ($_);
		1404	} elsif (exists $STR2LEVEL{$_} ) { $ctx->$level ($_);
		1405	} else { die "PERL_ANYEVENT_LOG ($spec): parse error at '$_'\n";
		1406	}
		1407	}
		1408
		1409	/\G,/gc or last;
		1410	}
		1411
		1412	/\G[:[:space:]]+/gc or last;
		1413	}
		1414
		1415	/\G[[:space:]]+/gc; # skip trailing whitespace
		1416
		1417	if (/\G(.+)/g) {
		1418	die "PERL_ANYEVENT_LOG ($spec): parse error at '$1'\n";
		1419	}
		1420	}
		1421
801	=head1 EXAMPLES	1422	=head1 EXAMPLES
802		1423
803	This section shows some common configurations.	1424	This section shows some common configurations, both as code, and as
		1425	C<PERL_ANYEVENT_LOG> string.
804		1426
805	=over 4	1427	=over 4
806		1428
807	=item Setting the global logging level.	1429	=item Setting the global logging level.
808		1430
809	Either put PERL_ANYEVENT_VERBOSE=<number> into your environment before	1431	Either put C<PERL_ANYEVENT_VERBOSE=><number> into your environment before
810	running your program, or modify the log level of the root context:	1432	running your program, use C<PERL_ANYEVENT_LOG> or modify the log level of
		1433	the root context at runtime:
811		1434
812	PERL_ANYEVENT_VERBOSE=5 ./myprog	1435	PERL_ANYEVENT_VERBOSE=5 ./myprog
813		1436
		1437	PERL_ANYEVENT_LOG=log=warn
		1438
814	$AnyEvent::Log::Root->level ("warn");	1439	$AnyEvent::Log::FILTER->level ("warn");
815		1440
816	=item Append all messages to a file instead of sending them to STDERR.	1441	=item Append all messages to a file instead of sending them to STDERR.
817		1442
818	This is affected by the global logging level.	1443	This is affected by the global logging level.
819		1444
820	open my $fh, ">>", $path	1445	$AnyEvent::Log::LOG->log_to_file ($path);
821	or die "$path: $!";
822		1446
823	$AnyEvent::Log::Default->log_cb (sub {	1447	PERL_ANYEVENT_LOG=log=file=/some/path
824	syswrite $fh, shift;
825	0
826	});
827		1448
828	=item Write all messages with priority C<error> and higher to a file.	1449	=item Write all messages with priority C<error> and higher to a file.
829		1450
830	This writes them only when the global logging level allows it, because	1451	This writes them only when the global logging level allows it, because
831	it is attached to the default context which is invoked I<after> global	1452	it is attached to the default context which is invoked I<after> global
832	filtering.	1453	filtering.
833		1454
834	open my $fh, ">>", $path	1455	$AnyEvent::Log::FILTER->attach (
835	or die "$path: $!";	1456	new AnyEvent::Log::Ctx log_to_file => $path);
836		1457
837	$AnyEvent::Log::Default->attach (new AnyEvent::Log::Ctx	1458	PERL_ANYEVENT_LOG=filter=+%filelogger:%filelogger=file=/some/path
838	log_cb => sub { syswrite $fh, shift; 0 });
839		1459
840	This writes them regardless of the global logging level, because it is	1460	This writes them regardless of the global logging level, because it is
841	attached to the toplevel context, which receives all messages I<before>	1461	attached to the toplevel context, which receives all messages I<before>
842	the global filtering.	1462	the global filtering.
843		1463
844	$AnyEvent::Log::Top->attach (new AnyEvent::Log::Ctx	1464	$AnyEvent::Log::COLLECT->attach (
845	log_cb => sub { syswrite $fh, shift; 0 });	1465	new AnyEvent::Log::Ctx log_to_file => $path);
846		1466
		1467	PERL_ANYEVENT_LOG=%filelogger=file=/some/path:collect=+%filelogger
		1468
847	In both cases, messages are still written to STDOUT.	1469	In both cases, messages are still written to STDERR.
		1470
		1471	=item Additionally log all messages with C<warn> and higher priority to
		1472	C<syslog>, but cap at C<error>.
		1473
		1474	This logs all messages to the default log target, but also logs messages
		1475	with priority C<warn> or higher (and not filtered otherwise) to syslog
		1476	facility C<user>. Messages with priority higher than C<error> will be
		1477	logged with level C<error>.
		1478
		1479	$AnyEvent::Log::LOG->attach (
		1480	new AnyEvent::Log::Ctx
		1481	level => "warn",
		1482	cap => "error",
		1483	syslog => "user",
		1484	);
		1485
		1486	PERL_ANYEVENT_LOG=log=+%syslog:%syslog=warn,cap=error,syslog
848		1487
849	=item Write trace messages (only) from L<AnyEvent::Debug> to the default logging target(s).	1488	=item Write trace messages (only) from L<AnyEvent::Debug> to the default logging target(s).
850		1489
851	Attach the CyAnyEvent::Log::Default> context to the C<AnyEvent::Debug>	1490	Attach the C<$AnyEvent::Log::LOG> context to the C<AnyEvent::Debug>
852	context and increase the C<AnyEvent::Debug> logging level - this simply
853	circumvents the global filtering for trace messages.	1491	context - this simply circumvents the global filtering for trace messages.
854		1492
855	my $debug = AnyEvent::Debug->AnyEvent::Log::ctx;	1493	my $debug = AnyEvent::Debug->AnyEvent::Log::ctx;
856	$debug->attach ($AnyEvent::Log::Default);	1494	$debug->attach ($AnyEvent::Log::LOG);
857	$debug->levels ("trace"); # not "level"!	1495
		1496	PERL_ANYEVENT_LOG=AnyEvent::Debug=+log
		1497
		1498	This of course works for any package, not just L<AnyEvent::Debug>, but
		1499	assumes the log level for AnyEvent::Debug hasn't been changed from the
		1500	default.
858		1501
859	=back	1502	=back
860		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
861	=head1 AUTHOR	1510	=head1 AUTHOR
862		1511
863	Marc Lehmann <schmorp@schmorp.de>	1512	Marc Lehmann <schmorp@schmorp.de>
864	http://home.schmorp.de/	1513	http://anyevent.schmorp.de
865		1514
866	=cut	1515	=cut
		1516
		1517	1
		1518

Diff Legend

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