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