NAME
Log::Defer - Deferred logs and timers
SYNOPSIS
use Log::Defer;
use JSON::XS; ## or whatever
use Try::Tiny;
sub my_logger_function {
my $msg = shift;
my $encoded_msg = try {
JSON::XS->new->pretty(1)->encode($msg)
}
catch {
"Failed to JSON encode msg : $_"
};
print $encoded_msg; ## usually you'd append this to a file
}
my $logger = Log::Defer->new({
cb => \&my_logger_function,
verbosity => 30,
});
$logger->info("hello world");
my $timer = $logger->timer('some timer');
undef $timer; ## stops timer
undef $logger; ## write out log message
Prints:
{
"start" : 1340421702.16684,
"end" : 0.000249,
"logs" : [
[
0.000147,
30,
"hello world"
]
],
"timers" : [
[
"some timer",
0.000210,
0.000233
]
]
}
DESCRIPTION
I believe a lot of log processing is done too early.
This module lets you defer log processing in two ways:
Defer recording of log messages until some "transaction" has completed
Typically this transaction is something like an HTTP request or a
cron job. Generally log messages are easier to read if they are
recorded atomically and are not intermingled with log messages
created by other transactions.
Defer rendering of log messages
Sometimes you don't know how logs should be rendered until long
after the message has been written. If you aren't sure what
information you'll want to display, or you expect to display the
same logs in multiple formats, it makes sense to store your logs in
a highly structured format so they can be reliably parsed and
processed later.
This module doesn't actually write out logs! To use this module for
normal logging purposes you also need a logging library (some of them
are mentioned in "SEE ALSO").
USAGE
To use Log::Defer, you create a logger object and pass in a code ref
callback (either bare or as "cb" in an argument hash-ref). This callback
will be called once the Log::Defer object is destroyed or once all
references to the object go out of scope:
sub handle_request {
my $logger = Log::Defer->new(\&logging_function);
...
$logger->info("blah blah");
...
} ## <- $logger goes out of scope here so log is written now
There is no need to manually ensure that every possible code path ends
up calling your logging routine at the end because perl's reference
counting system does that for you (unless you call "POSIX::_exit" so
don't do that).
In an asynchronous application where multiple asynchronous tasks are
kicked off concurrently, each task can keep a reference to the logger
object and the log writing will be deferred until all tasks are
finished.
Log::Defer makes it easy to gather timing information about the various
stages of your request. This is explained further below.
STRUCTURED LOGS
Free-form line-based log protocols are probably the most common log
formats by far. The "format" is usually just coincidental -- whatever
happened to be convenient for the programmer to record.
Unfortunately, doing analysis on ad-hoc unstructured logs requires lots
of menial coding work writing parsers. Even more annoying is that these
parsers are often regexp-based and brittle.
As well as being a perl module, Log::Defer is also a specification for a
structured logging format. Although it doesn't impose any external
encoding for log messages on you, some tools like the visualisation tool
log-defer-viz only support JSON at this time.
The currently recommended format to store logs in is newline-separated,
minified JSON. The newline+minification is useful because it allows
simple whole-request greping of the logs. With structured logs, much
more accurate and flexible greping is also possible, as described in
log-defer-viz.
LOG MESSAGES
Log::Defer objects provide a very basic "log level" system. In order of
increasing verbosity, here are the normal logging methods and their
numeric log levels:
$logger->error("..."); # 10
$logger->warn("..."); # 20
$logger->info("..."); # 30
$logger->debug("..."); # 40
You can also use custom log levels:
$logger->add_log(25, "...");
If you pass in a "verbosity" argument to the Log::Defer constructor,
messages with a higher log level will not be included in the final log
message. Otherwise, all log messages are included.
Even if you record noisy debug logs you can filter them out with a
visualisation tool at display time. The "verbosity" argument is only
useful for reducing the size of log messages or eliminating unnecessary
processing overhead (see the no-overhead debug logs section below).
Note that you can pass in multiple items to a log message and they don't
even need to be strings (but make sure you are handling any
serialisation exceptions thrown by your encoder as done in the
synopsis):
$logger->error("peer timeout", { waited => $timeout });
In the deferred logging callback, the log messages are recorded in the
"logs" element of the $msg hash. It is an array ref and here is the
element that would be pushed onto "logs" by the "error" method call
above:
[ 30.201223, 10, "peer timeout", { waited => 30 } ]
The first element is a timestamp of how long the "error" method was
called after the "start" in seconds (see TIMERS below). The second
element is the verbosity level of this message. The remaining elements
are passed in untouched from the "error" method.
NO-OVERHEAD DEBUG LOGS
If you would like to compute complex messages in debug mode but don't
want to burden your production systems with this overhead, you can use
delayed message generation:
$logger->debug(sub { "Connection: " . dump_connection_info($conn) });
The sub will only be invoked if the logger object is instantiated with
"verbosity" of 40 or higher (or you omit "verbosity" altogether).
DATA
Instead of log messages, you can directly add items to a "data" hash
reference with the "data" method:
$log->data->{ip} = $ENV{REMOTE_ADDR};
This is a useful place to record info that needs to be extracted
programatically. Anything you put in the "data" hash reference will be
passed along untouched to your defered callback (but again, make sure
you are catching encoder exceptions as shown in the synopsis).
TIMERS
When the logger object is first created, the current time is recorded as
a Time::HiRes absolute timestamp and is stored in the "start" element of
the log hash. "start" is a Time::HiRes absolute timestamp. All other
times are relative offsets from "start" in seconds.
When the logger object is destroyed, the time elapsed since "start" is
stored in "end".
In addition to the start and duration of the entire transaction, you can
also record timing data of sub-portions of your transaction by using
timer objects.
Timer objects are created by calling the "timer" method on the logger
object. This method should be passed a description of what you are
timing.
The timer starts as soon as the timer object is created and stops once
the last reference to the timer is destroyed or goes out of scope:
{
my $timer = $log_defer_object->timer('running some_code()');
some_code();
} ## <- timer is stopped here because $timer goes out of scope
If the logger object itself is destroyed or goes out of scope then all
outstanding timers are terminated at that point.
EXAMPLE LOG MESSAGE
Each structured log message will be passed into the callback provided to
"new" as a perl hash reference that contains various other perl
data-structures. What you do at this point is up to you.
Here is a prettified example of a JSON-encoded message:
{
"start" : 1340353046.93565,
"end" : 0.202386,
"logs" : [
[
0.000158,
30,
"This is an info message (log level=30)"
],
[
0.201223,
20,
"Warning! \n\n Here is some more data:",
{
"whatever" : 987
}
]
],
"data" : {
"junkdata" : "some data"
},
"timers" : [
[
"junktimer",
0.000224,
0.100655
],
[
"junktimer2",
0.000281,
0.202386
]
]
}
VISUALISATION
See the log-defer-viz command-line script that renders Log::Defer logs.
Timers are shown something like this:
download file |===============================================|
cache lookup |==============|
DB lookup |======================|
update cache |==================|
sent reply X
________________________________________________________________________________
times in ms 0.2 32.4 100.7
80.7 119.2
MERGING
Sometimes it's useful to create a "child logger" Log::Defer object which
is later merged into your main logger. This can be accomplished with the
"merge" method:
my $logger = Log::Defer->new(sub {
my $merged_msg = shift;
## ...
});
## ...
{
my $child_logger = Log::Defer->new(sub {
my $msg = shift;
$logger->merge($msg);
});
}
## ...
This technique is used in AnyEvent::Task so that worker processes can
log messages using Log::Defer and these are then merged into a client
process's existing logger object.
SEE ALSO
Log::Defer github repo <https://github.com/hoytech/Log-Defer>
One way to visualize logs created by this module is with the
command-line script log-defer-viz
Michael Pucyk has created a Python implementation for the Log::Defer
format: LogDefer Python module <https://github.com/mikep/LogDefer>
As mentioned above, this module doesn't itself log messages to disk so
you still must use some other module to record your log messages. There
are many libraries on CPAN that can do this and there should be at least
one that fits your requirements. Some examples are: Sys::Syslog,
Log::Dispatch, Log::Handler, Log::Log4perl, Log::Fast, AnyEvent::Log.
Additionally, this module doesn't provide any official serialization
format. There are many choices for this, including JSON::XS (JSON is the
only format currently supported by log-defer-viz), Sereal, Storable, and
Data::MessagePack.
Currently the timestamp generation system is hard-coded to
"Time::HiRes::time". You should be aware of some caveats related to
non-monotonous clocks that are discussed in Time::HiRes.
AUTHOR
Doug Hoyte, "<doug@hcsw.org>"
COPYRIGHT & LICENSE
Copyright 2012-2014 Doug Hoyte.
This module is licensed under the same terms as perl itself.