1# $Id: /mirror/gungho/lib/Gungho/Plugin/RequestLog.pm 31117 2007-11-26T13:10:33.379262Z lestrrat  $
2#
3# Copyright (c) 2007 Daisuke Maki <daisuke@endeworks.jp>
4# All rights reserved.
5
6package Gungho::Plugin::RequestLog;
7use strict;
8use warnings;
9use base qw(Gungho::Plugin);
10use Gungho::Log::Dispatch;
11
12BEGIN
13{
14    eval "use Time::HiRes";
15    if (! $@) {
16        Time::HiRes->import( 'time' );
17    }
18}
19
20__PACKAGE__->mk_accessors($_) for qw(log);
21
22sub setup
23{
24    my ($self, $c) = @_;
25
26    my $log = Gungho::Log::Dispatch->new(config => {
27        logs      => $self->config,
28        callbacks => sub {
29            my %args = @_;
30            my $message = $args{message};
31            if ($message !~ /\n$/) {
32                $message =~ s/$/\n/;
33            }
34            return $message;
35        },
36    });
37    $log->setup($c);
38    $self->log($log);
39
40    $c->register_event('engine.send_request' => sub { $self->log_request(@_) } );
41    $c->register_event('engine.handle_response' => sub { $self->log_response(@_) } );
42}
43
44sub log_request
45{
46    my ($self, $event, $c, $data) = @_;
47
48    # Only log this if we've been asked to do soA
49    my $request = $data->{request};
50    my $uri     = $request->original_uri;
51    my $time    = time();
52    $request->notes('send_request_time' => $time);
53    $self->log->debug(sprintf("# %s | %s | %s", $time, $uri, $request->id));
54}
55
56sub log_response
57{
58    my ($self, $event, $c, $data) = @_;
59
60    my( $request, $response ) = ($data->{request}, $data->{response});
61    my $time = time();
62    my $send_time = $request->notes('send_request_time');
63
64    # It's quite possible that we're dealing with a request that was sent
65    # when this plugin wasn't loaded. In that case, do not calculate the
66    # time elapsed
67    my $elapsed;
68    if(! defined $send_time ) {
69        $elapsed = "(UNKNOWN)";
70    } else {
71        $elapsed = $time - $send_time;
72    }
73
74    $request->notes('handle_response_time' => $time);
75    $request->notes('total_request_time'   => $elapsed);
76    $self->log->info(sprintf("%s | %s | %s | %s | %s", $time, $elapsed, $response->code, $request->original_uri, $request->id));
77}
78
791;
80
81__END__
82
83=head1 NAME
84
85Gungho::Plugin::RequestLog - Log Requests
86
87=head1 SYNOPSIS
88
89  plugins:
90    - module: RequestLog
91      config:
92        - module: File
93          file: /path/to/filename
94
95=head1 DESCRIPTION
96
97If you want to know what Gungho's fetching, load this plugin.
98
99The regular logs are logged at 'info' level, so don't set min_level to above
100'info' in the config. See Log::Dipatch for details.
101
102=head1 LOG FORMAT
103
104The basic log format is
105
106  CURRENT_TIME | ELAPSED TIME | RESPONSE CODE | URI | REQUEST ID
107
108For the rare cases where for some reason you believe the request has been
109requested to be fetched but the response isn't coming back, set the
110min_level of the log config to debug:
111
112  plugins:
113    - module: RequestLog
114      config:
115        - module: File
116          file: /path/to/filename
117          min_level: debug
118
119When you enable debug, lines like this will be logged at send_request time
120
121  # CURRENT_TIME | URI | REQUEST ID
122
123The leading '#' is there to aid you filter out the logs
124
125=head1 METHODS
126
127=head2 setup
128
129=head2 log_request
130
131=head2 log_response
132
133=cut
134