[Jifty-commit] jifty-plugin-accesslog branch, master, updated. 1.0-6-gd7eb861

Jifty commits jifty-commit at lists.jifty.org
Fri May 21 21:44:42 EDT 2010


The branch, master has been updated
       via  d7eb861939bad1e959901f285deb2880b32a431c (commit)
       via  f0f292686c64835503bc0438e986e82b1e75712c (commit)
       via  e1682064d69f168025acc92c36ecb99250fc8149 (commit)
       via  4c7367fd937cb5888d542a004969e778abb48990 (commit)
       via  ebdd2724f2529c412468f18cbc50cf3497dd5948 (commit)
      from  1b0acec53764bd0bd316e384f2507898cfe777a6 (commit)

Summary of changes:
 lib/Jifty/Plugin/AccessLog.pm |   94 ++++++++++++++++++++++++++++++++++-------
 1 files changed, 78 insertions(+), 16 deletions(-)

- Log -----------------------------------------------------------------
commit ebdd2724f2529c412468f18cbc50cf3497dd5948
Author: Alex Vandiver <alexmv at bestpractical.com>
Date:   Fri May 21 18:08:35 2010 -0400

    Move from CGI::Cookie, which looks at ENV, to plack's way of cookie handling

diff --git a/lib/Jifty/Plugin/AccessLog.pm b/lib/Jifty/Plugin/AccessLog.pm
index 053693b..4af0fc6 100644
--- a/lib/Jifty/Plugin/AccessLog.pm
+++ b/lib/Jifty/Plugin/AccessLog.pm
@@ -5,7 +5,6 @@ use base qw/Jifty::Plugin Class::Data::Inheritable/;
 __PACKAGE__->mk_accessors(qw/path format start respect_proxy/);
 
 use Jifty::Util;
-use CGI::Cookie;
 use Time::HiRes qw();
 
 our $VERSION = 1.0;
@@ -213,7 +212,7 @@ sub before_cleanup {
     my %ESCAPES = (
         '%' => sub { '%' },
         a => sub { ($self->respect_proxy && $r->header("X-Forwarded-For")) || $r->address },
-        C => sub { my $c = { CGI::Cookie->fetch() }->{+shift}; $c ? $c->value : undef },
+        C => sub { $r->cookies->{+shift} },
         D => sub { sprintf "%.3fms", (Time::HiRes::time - $self->start)*1000 },
         e => sub { $r->env->{+shift} },
         h => sub { ($self->respect_proxy && $r->header("X-Forwarded-For")) || $r->remote_host || $r->address },

commit 4c7367fd937cb5888d542a004969e778abb48990
Author: Alex Vandiver <alexmv at bestpractical.com>
Date:   Fri May 21 19:27:01 2010 -0400

    Don't try set the status -- plack does this automatically all the time now

diff --git a/lib/Jifty/Plugin/AccessLog.pm b/lib/Jifty/Plugin/AccessLog.pm
index 4af0fc6..8bbc5f5 100644
--- a/lib/Jifty/Plugin/AccessLog.pm
+++ b/lib/Jifty/Plugin/AccessLog.pm
@@ -183,8 +183,6 @@ Open, and append to, the logfile with the format specified.
 sub before_cleanup {
     my $self = shift;
     my $r    = Jifty->web->request;
-    Jifty->web->response->status(200)
-      unless defined Jifty->web->response->status;
 
     my $actions = sub {
         my $long = shift;

commit e1682064d69f168025acc92c36ecb99250fc8149
Author: Alex Vandiver <alexmv at bestpractical.com>
Date:   Fri May 21 19:28:10 2010 -0400

    Split formatting code into its own subroutine

diff --git a/lib/Jifty/Plugin/AccessLog.pm b/lib/Jifty/Plugin/AccessLog.pm
index 8bbc5f5..8cf3ae1 100644
--- a/lib/Jifty/Plugin/AccessLog.pm
+++ b/lib/Jifty/Plugin/AccessLog.pm
@@ -174,13 +174,13 @@ sub new_request {
     $self->start(Time::HiRes::time);
 }
 
-=head2 before_cleanup
+=head2 format_req
 
-Open, and append to, the logfile with the format specified.
+Return the formatted string to log
 
 =cut
 
-sub before_cleanup {
+sub format_req {
     my $self = shift;
     my $r    = Jifty->web->request;
 
@@ -258,15 +258,24 @@ sub before_cleanup {
         return defined $r ? $r : "-";
     };
 
-
     my $s = $self->format;
     $s =~ s/%(\d+(?:,\d+)*)?(?:{(.*?)})?([a-zA-Z%])/$replace->($1,$2,$3)/ge;
+    return $s;
+}
+
+=head2 before_cleanup
 
+Write the access log line to the file
+
+=cut
+
+sub before_cleanup {
+    my $self = shift;
     open my $access_log, '>>', $self->path or do {
         $self->log->error("Unable to open @{[$self->path]} for writing: $!");
         return;
     };
-    $access_log->syswrite( "$s\n" );
+    $access_log->syswrite( $self->format_req . "\n" );
     $access_log->close;
 }
 

commit f0f292686c64835503bc0438e986e82b1e75712c
Author: Alex Vandiver <alexmv at bestpractical.com>
Date:   Fri May 21 19:30:02 2010 -0400

    Report any errors while formatting log messages

diff --git a/lib/Jifty/Plugin/AccessLog.pm b/lib/Jifty/Plugin/AccessLog.pm
index 8cf3ae1..776789e 100644
--- a/lib/Jifty/Plugin/AccessLog.pm
+++ b/lib/Jifty/Plugin/AccessLog.pm
@@ -251,7 +251,8 @@ sub format_req {
         }
         my $r;
         if (exists $ESCAPES{$format}) {
-            $r = ref $ESCAPES{$format} ? eval {$ESCAPES{$format}->($string)} : $ESCAPES{$format};
+            $r = eval { $ESCAPES{$format}->($string) };
+            $self->log->warn("While formatting $format, got $@") if $@;
         } else {
             $r = "%".$format;
         }

commit d7eb861939bad1e959901f285deb2880b32a431c
Author: Alex Vandiver <alexmv at bestpractical.com>
Date:   Fri May 21 19:30:19 2010 -0400

    Add support for logging "partial requests" which never finish
    
    This introduces configurable "partial" logfiles, which are per-process
    logfiles which should only ever have 0 or 1 request in them.  As soon
    as possible in the request, we write out the information we have to
    these files -- as soon as the request is successful and written to the
    permanent logfile, we rewind and truncate the log message.  This means
    that any non-empty files pinpoint requests which were never completed,
    and bear examination.

diff --git a/lib/Jifty/Plugin/AccessLog.pm b/lib/Jifty/Plugin/AccessLog.pm
index 776789e..d6aa9d4 100644
--- a/lib/Jifty/Plugin/AccessLog.pm
+++ b/lib/Jifty/Plugin/AccessLog.pm
@@ -2,7 +2,7 @@ package Jifty::Plugin::AccessLog;
 use strict;
 use warnings;
 use base qw/Jifty::Plugin Class::Data::Inheritable/;
-__PACKAGE__->mk_accessors(qw/path format start respect_proxy/);
+__PACKAGE__->mk_accessors(qw/path format start respect_proxy partials partial_fh/);
 
 use Jifty::Util;
 use Time::HiRes qw();
@@ -135,6 +135,14 @@ As C<%X>, but also includes all argument values to each action.
 
 =back
 
+=item partials
+
+The prefix to log partial logfiles to.  These files are written to as
+soon as a request comes in, and truncated back to empty after it is
+written to the final logfile.  Non-empty partial logfiles contain
+requests which are the cause of critical errors, and should be
+examined more closely.
+
 =back
 
 =head2 METHODS
@@ -161,6 +169,10 @@ sub init {
     Jifty::Handler->add_trigger(
         before_cleanup => sub { $self->before_cleanup }
     );
+
+    Jifty::Handler->add_trigger(
+        have_request => sub { $self->have_request },
+    ) if $self->partials;
 }
 
 =head2 new_request
@@ -218,7 +230,7 @@ sub format_req {
         l => sub { substr( Jifty->web->session->id || '-', 0, 8 ) },
         m => sub { $r->method },
         n => sub { $r->template_argument($_[0]) || $r->argument($_[0]) },
-        o => sub { Jifty->web->response->header(shift) },
+        o => sub { $self->start and Jifty->web->response->header(shift) },
         p => sub {
             return Jifty->config->framework("Web")->{Port} if $_[0] eq "canonical";
             return $r->env->{SERVER_PORT} if $_[0] eq "local";
@@ -226,10 +238,10 @@ sub format_req {
             return Jifty->config->framework("Web")->{Port};
         },
         P => sub { $$ },
-        s => sub { Jifty->web->response->status =~ /^(\d+)/; $1 || "200" },
-        t => sub { DateTime->from_epoch(epoch => $self->start)->strftime(shift || "[%d/%b/%Y:%T %z]") },
-        T => sub { sprintf "%.3fs", (Time::HiRes::time - $self->start) },
-        u => sub { Jifty->web->current_user->username },
+        s => sub { $self->start and Jifty->web->response->status =~ /^(\d+)/ and $1 },
+        t => sub { $self->start and DateTime->from_epoch(epoch => $self->start)->strftime(shift || "[%d/%b/%Y:%T %z]") },
+        T => sub { $self->start and sprintf("%.3fs", (Time::HiRes::time - $self->start)) },
+        u => sub { $self->start and Jifty->web->current_user->username },
         U => sub {
             if (my @f = $r->fragments) {
                 return '[' . join(" ", map {s/ /%20/g;$_} map {$_->path} @f ) . ']';
@@ -247,6 +259,7 @@ sub format_req {
     my $replace = sub {
         my ($only_on, $string, $format) = @_;
         if (defined $only_on) {
+            return "" unless defined Jifty->web->response->status;
             return "" unless grep {Jifty->web->response->status eq $_} split /,/, $only_on;
         }
         my $r;
@@ -278,6 +291,48 @@ sub before_cleanup {
     };
     $access_log->syswrite( $self->format_req . "\n" );
     $access_log->close;
+    $self->start(undef);
+    # Once the request has been written to the actual access log, we
+    # purge the partial request from disk
+    if ($self->partial_fh) {
+        seek($self->partial_fh, 0, 0);
+        truncate($self->partial_fh, 0);
+    }
+}
+
+=head2 have_request
+
+Write the incoming request to the partial logfile; this is only called
+if partial logfiles are configured.
+
+=cut
+
+sub have_request {
+    my $self = shift;
+    unless ($self->partial_fh) {
+        open my $fh, ">>", $self->partials.$$ or do {
+            $self->log->error("Unable to open @{[$self->partials]}$$ partial for writing: $!");
+            return;
+        };
+        $self->partial_fh($fh);
+    }
+    $self->partial_fh->syswrite( $self->format_req . "\n" );
+}
+
+=head2 END
+
+When the process terminates, remove partial logfiles which are empty.
+
+=cut
+
+END {
+    # Purge any empty partial request logs, but leave ones which have
+    # data in them
+    for my $plugin (grep {$_->isa("Jifty::Plugin::AccessLog") and $_->partial_fh} Jifty->plugins) {
+        next if $plugin->partial_fh->tell;
+        $plugin->partial_fh->close;
+        unlink($plugin->partials.$$);
+    }
 }
 
 =head1 SEE ALSO

-----------------------------------------------------------------------


More information about the Jifty-commit mailing list