prettier logs
[catagits/Catalyst-Runtime.git] / lib / Catalyst / Engine.pm
index d8d47b5..13fcdc0 100644 (file)
@@ -9,6 +9,7 @@ use HTML::Entities;
 use HTTP::Headers;
 use Memoize;
 use Time::HiRes qw/gettimeofday tv_interval/;
+use Text::ASCIITable;
 use Tree::Simple;
 use Tree::Simple::Visitor::FindByPath;
 use Catalyst::Request;
@@ -133,11 +134,10 @@ sub execute {
         {
             my $action = $c->actions->{reverse}->{"$code"};
             $action = "/$action" unless $action =~ /\-\>/;
-            $action = "  $action" if $callsub =~ /forward$/;
+            $action = "    $action" if $callsub =~ /forward$/;
             my ( $elapsed, @state ) =
               $c->benchmark( $code, $class, $c, @{ $c->req->args } );
-            push @{ $c->{stats} },
-              _prettify_stats( $action, sprintf( '%fs', $elapsed ), '' );
+            push @{ $c->{stats} }, [ $action, sprintf( '%fs', $elapsed ) ];
             $c->state(@state);
         }
         else { $c->state( &$code( $class, $c, @{ $c->req->args } ) ) }
@@ -459,7 +459,8 @@ sub handler {
                 for my $begin ( @{ $c->get_action( 'begin', $namespace ) } ) {
                     $c->state( $c->execute( @{ $begin->[0] } ) );
                 }
-                for my $result ( @{ $c->get_action( $action, $default ) }[-1] )
+                for my $result (
+                    @{ $c->get_action( $c->req->action, $default ) }[-1] )
                 {
                     $c->state( $c->execute( @{ $result->[0] } ) );
                     last unless $default;
@@ -484,7 +485,16 @@ sub handler {
             ( $elapsed, $status ) = $class->benchmark($handler);
             $elapsed = sprintf '%f', $elapsed;
             my $av = sprintf '%.3f', 1 / $elapsed;
-            $class->log->info( "Request took $elapsed" . "s ($av/s)", @stats );
+            my $t = Text::ASCIITable->new;
+            $t->setCols( 'Action', 'Time' );
+            $t->setColWidth( 'Action', 64, 1 );
+            $t->setColWidth( 'Time',   9,  1 );
+
+            for my $stat (@stats) {
+                $t->addRow(@$stat);
+            }
+            $class->log->info( "Request took $elapsed" . "s ($av/s)",
+                $t->draw );
         }
         else { $status = &$handler }
     };
@@ -525,9 +535,9 @@ sub prepare {
     if ( $c->debug ) {
         my $secs = time - $START || 1;
         my $av = sprintf '%.3f', $COUNT / $secs;
-        $c->log->debug('********************************');
+        $c->log->debug('**********************************');
         $c->log->debug("* Request $COUNT ($av/s) [$$]");
-        $c->log->debug('********************************');
+        $c->log->debug('**********************************');
         $c->res->headers->header( 'X-Catalyst' => $Catalyst::VERSION );
     }
     $c->prepare_request($r);
@@ -545,12 +555,15 @@ sub prepare {
     $c->prepare_parameters;
 
     if ( $c->debug && keys %{ $c->req->params } ) {
-        my @params;
+        my $t = Text::ASCIITable->new;
+        $t->setCols( 'Key', 'Value' );
+        $t->setColWidth( 'Key',   37, 1 );
+        $t->setColWidth( 'Value', 36, 1 );
         for my $key ( keys %{ $c->req->params } ) {
             my $value = $c->req->params->{$key} || '';
-            push @params, "  $key=$value";
+            $t->addRow( $key, $value );
         }
-        $c->log->debug( 'Parameters are', @params );
+        $c->log->debug( 'Parameters are', $t->draw );
     }
     $c->prepare_uploads;
     return $c;
@@ -575,7 +588,8 @@ sub prepare_action {
             if ($#$result) {
                 my $match    = $result->[1];
                 my @snippets = @{ $result->[2] };
-                $c->log->debug(qq/Requested action "$path" matched "$match"/)
+                $c->log->debug(
+                    qq/Requested action is "$path" and matched "$match"/)
                   if $c->debug;
                 $c->log->debug(
                     'Snippets are "' . join( ' ', @snippets ) . '"' )
@@ -585,7 +599,7 @@ sub prepare_action {
             }
             else {
                 $c->req->action($path);
-                $c->log->debug(qq/Requested action "$path"/) if $c->debug;
+                $c->log->debug(qq/Requested action is "$path"/) if $c->debug;
             }
             $c->req->match($path);
             last;
@@ -844,39 +858,55 @@ sub setup_components {
         $self->components->{ ref $comp } = $comp;
         $self->setup_actions($comp);
     }
-    my @comps;
-    push @comps, "  $_" for keys %{ $self->components };
-    $self->log->debug( 'Loaded components', @comps )
-      if ( @comps && $self->debug );
+    my $t = Text::ASCIITable->new;
+    $t->setCols('Class');
+    $t->setColWidth( 'Class', 75, 1 );
+    $t->addRow($_) for keys %{ $self->components };
+    $self->log->debug( 'Loaded components', $t->draw )
+      if ( @{ $t->{tbl_rows} } && $self->debug );
     my $actions  = $self->actions;
-    my @messages = ('Loaded private actions');
-    my $walker   = sub {
-        my ( $walker, $parent, $messages, $prefix ) = @_;
+    my $privates = Text::ASCIITable->new;
+    $privates->setCols( 'Action', 'Class', 'Code' );
+    $privates->setColWidth( 'Action', 28, 1 );
+    $privates->setColWidth( 'Class',  28, 1 );
+    $privates->setColWidth( 'Code',   14, 1 );
+    my $walker = sub {
+        my ( $walker, $parent, $prefix ) = @_;
         $prefix .= $parent->getNodeValue || '';
         $prefix .= '/' unless $prefix =~ /\/$/;
         my $uid = $parent->getUID;
         for my $action ( keys %{ $actions->{private}->{$uid} } ) {
             my ( $class, $code ) = @{ $actions->{private}->{$uid}->{$action} };
-            push @$messages,
-              _prettify_action( "$prefix$action", $class, $code );
+            $privates->addRow( "$prefix$action", $class, $code );
         }
-        $walker->( $walker, $_, $messages, $prefix )
-          for $parent->getAllChildren;
+        $walker->( $walker, $_, $prefix ) for $parent->getAllChildren;
     };
-    $walker->( $walker, $self->tree, \@messages, '' );
-    $self->log->debug(@messages) if ( $#messages && $self->debug );
-    @messages = ('Loaded plain actions');
+    $walker->( $walker, $self->tree, '' );
+    $self->log->debug( 'Loaded private actions', $privates->draw )
+      if ( @{ $privates->{tbl_rows} } && $self->debug );
+    my $publics = Text::ASCIITable->new;
+    $publics->setCols( 'Action', 'Class', 'Code' );
+    $publics->setColWidth( 'Action', 28, 1 );
+    $publics->setColWidth( 'Class',  28, 1 );
+    $publics->setColWidth( 'Code',   14, 1 );
+
     for my $plain ( sort keys %{ $actions->{plain} } ) {
         my ( $class, $code ) = @{ $actions->{plain}->{$plain} };
-        push @messages, _prettify_action( "/$plain", $class, $code );
-    }
-    $self->log->debug(@messages) if ( $#messages && $self->debug );
-    @messages = ('Loaded regex actions');
+        $publics->addRow( "/$plain", $class, $code );
+    }
+    $self->log->debug( 'Loaded public actions', $publics->draw )
+      if ( @{ $publics->{tbl_rows} } && $self->debug );
+    my $regexes = Text::ASCIITable->new;
+    $regexes->setCols( 'Action', 'Class', 'Code' );
+    $regexes->setColWidth( 'Action', 28, 1 );
+    $regexes->setColWidth( 'Class',  28, 1 );
+    $regexes->setColWidth( 'Code',   14, 1 );
     for my $regex ( sort keys %{ $actions->{regex} } ) {
         my ( $class, $code ) = @{ $actions->{regex}->{$regex} };
-        push @messages, _prettify_action( $regex, $class, $code );
+        $regexes->addRow( $regex, $class, $code );
     }
-    $self->log->debug(@messages) if ( $#messages && $self->debug );
+    $self->log->debug( 'Loaded regex actions', $regexes->draw )
+      if ( @{ $regexes->{tbl_rows} } && $self->debug );
 }
 
 =item $c->stash
@@ -916,25 +946,6 @@ sub _class2prefix {
     return $prefix;
 }
 
-sub _prettify_action {
-    my ( $val1, $val2, $val3 ) = @_;
-    formline
-'  @<<<<<<<<<<<<<<<<<<<<<<<<<<<<< @<<<<<<<<<<<<<<<<<<<<<<<<<<<< @>>>>>>>>>>>>>>  ',
-      $val1, $val2, $val3;
-    my $formatted = $^A;
-    $^A = '';
-    return $formatted;
-}
-
-sub _prettify_stats {
-    my ( $val1, $val2 ) = @_;
-    formline '  @<<<<<<<<<<<<<<<<<<<<<<<<<<<<< @<<<<<<<<<<<<<<<<<<<<<<<<<<<< ',
-      $val1, $val2;
-    my $formatted = $^A;
-    $^A = '';
-    return $formatted;
-}
-
 =back
 
 =head1 AUTHOR