NAME

Log::Defer - Deferred logs and timers

SYNOPSIS

    use Log::Defer;
    use JSON::XS; ## or whatever

    my $logger = Log::Defer->new(\&my_logger_function);
    $logger->info("hello world");
    undef $logger; # write out log message

    sub my_logger_function {
      my $msg = shift;
      print JSON::XS->new->pretty(1)->encode($msg);
    }

Prints:

    {
       "start" : 1340421702.16684,
       "end" : 0.000249,
       "logs" : [
          [
             0.000147,
             30,
             "hello world"
          ]
       ]
    }

DESCRIPTION

This module doesn't actually log anything! To use this module for normal logging purposes you also need a logging library (some of them are mentioned in "SEE ALSO").

What this module does is allow you to defer recording log messages until after some kind of "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.

This module preserves as much structure as possible which allows you to record machine-parseable log messages if you so choose.

USAGE

The simplest use case is outlined in the SYNOPSIS. You create a new Log::Defer object and pass in a code ref. This code ref will be called once the Log::Defer object is destroyed or all references to the object go out of scope.

If a transaction has several possible paths it can take, there is no need to manually ensure that every possible path ends up calling your logging routine at the end. The log writing will be deferred until the logger object is destroyed or goes out of scope.

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

So what is the point of this module? Most logging libraries are convenient to use, usually even more-so than Log::Defer. However, this module allows you to record log messages in a format that can be easily analysed if you so choose.

Line-based log protocols are nice because they are compact and since people are used to them they are "easy" to read.

However, doing analysis on line-based or, even worse, ad-hoc unstructured multi-line formats is more difficult than it needs to be. And given the right tools, reading structured log messages can actually be easier than reading line-based logs.

LOG MESSAGES

Log::Defer objects provide a very basic "log level" system. In order of increasing verbosity, here are the possible logging methods:

    $logger->error("...");  # 10
    $logger->warn("...");   # 20
    $logger->info("...");   # 30
    $logger->debug("...");  # 40

The only thing that this module does with the log level is record it in the log message.

Here is an example of issuing a warning:

    $logger->warn("something weird happened", { username => $username });

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 would be the element pushed onto logs by the warn method call above:

    [ 0.201223, 20, "something weird happened", { username => "jimmy" } ]

The first element is a timestamp of when the warn method was called in seconds since the start (see TIMERS below).

The second element is the verbosity level. If you wish to implement "log levels" (ie filter out debug messages), you can grep them out when your recording callback is called.

DATA

Instead of log messages, you can directly access a data hash reference with the data method:

    $log->data->{junkdata} = 'some data';

This is useful for recording info related to a whole transaction like say a connecting IP address. Anything you put in the data hash reference will be passed along untouched to your defered callback.

TIMERS

Timer objects can be 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 only stops once the last reference to the timer is destroyed or goes out of scope, or if the logger object itself is destroyed/goes out of scope.

When the logger object is first created, the current time is recorded 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 this start time. Everything is in seconds.

Here is a fairly complicated example that includes concurrent timers:

    sub handle_request {
      my $request = shift;
      my $logger = Log::Defer->new(\&my_logging_function);

      my $headers = do {
        my $parse_timer = $logger->timer('parsing request');
        parse_request($request);
      };

      my $fetch_timer = $logger->timer('fetching results');
      async_fetch_results($headers, sub {

        ## stop first timer by undefing ref, then start new timer
        undef $fetch_timer; $fetch_timer = $logger->timer('fetching stage 2');

        async_fetch_stage_2($headers, sub {

          $logger; ## keep reference alive
          undef $fetch_timer;
          send_response();

        });

        my $update_cache_timer = $logger->timer('update cache');

        async_update_cach(sub {

          $logger; ## keep reference alive
          undef $update_cache_timer;

        });

      });
    }

EXAMPLE LOG MESSAGE

Each structured log message will be passed into the callback provided to new. The message is a perl hash reference that contains various other perl data-structures. What you do at this point is up to you.

What follows is a prettified example of a JSON-encoded log message. Normally all unnecessary white-space would be removed and it would be stored on a single line so that ad-hoc command-line greping still works.

    {
       "start" : 1340353046.93565,
       "end" : 0.202386,
       "logs" : [
          [
             0.000158,
             30,
             "This is an info message (verbosity=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
          ]
       }
    }

FUTURE WORK

We plan do some cool stuff with structured logs. Here's a mock-up of a timer rendering idea:

    parsing request       |======|
    fetching results             |==========|
    fetching stage 2                        |==========================|
    update cache                            |==========|
                          0                 0.05073                    0.129351
                                 0.0012                 0.084622

SEE ALSO

As mentioned above, this module doesn't actually log messages to disk/syslog/anything 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.

Some caveats related to non-monotonous clocks are discussed in Time::HiRes.

AUTHOR

Doug Hoyte, <doug@hcsw.org>

COPYRIGHT & LICENSE

Copyright 2012 Doug Hoyte.

This module is licensed under the same terms as perl itself.

cpanm Log::Defer

perl -MCPAN -e shell
install Log::Defer