logging, tracing, and perltidy, ...

...plus renamed a couple of log events for consistency

src/Gitolite/Common.pm

@@ -39,6 +39,8 @@ sub say2 {
 }
 
 sub trace {
+    gl_log( "\t" . join( ",", @_[ 1 .. $#_ ] ) ) if $_[0] <= 1 and defined $Gitolite::Rc::rc{LOG_EXTRA};
+
     return unless defined( $ENV{D} );
 
     my $level = shift; return if $ENV{D} < $level;
@@ -111,8 +113,7 @@ sub _chdir {
 sub _system {
     # run system(), catch errors.  Be verbose only if $ENV{D} exists.  If not,
     # exit with <rc of system()> if it applies, else just "exit 1".
-    trace( 2, @_ );
+    trace( 1, 'system', @_ );
-    gl_log( 'system', @_ );
     if ( system(@_) != 0 ) {
         trace( 1, "system() failed", @_, "-> $?" );
         if ( $? == -1 ) {
@@ -238,6 +239,8 @@ sub gl_log {
     # the log filename and the timestamp come from the environment.  If we get
     # called even before they are set, we have no choice but to dump to STDERR
     # (and probably call "logger").
+
+    # tab sep if there's more than one field
     my $msg = join( "\t", @_ );
     $msg =~ s/[\n\r]+/<<newline>>/g;
 

src/Gitolite/Conf/Explode.pm

@@ -86,7 +86,7 @@ sub prefix_groupnames {
     if ($lhs) {
         $line =~ s/^@\S+ = /"\@$subconf.$lhs = "/e;
         $prefixed_groupname{$subconf}{"\@$lhs"} = "\@$subconf.$lhs";
-        trace( 2, "prefixed_groupname.$subconf.\@$lhs = \@$subconf.$lhs" );
+        trace( 3, "prefixed_groupname.$subconf.\@$lhs = \@$subconf.$lhs" );
     }
 
     return $line;
@@ -105,7 +105,7 @@ sub already_included {
 
 sub device_inode {
     my $file = shift;
-    trace( 2, $file, ( stat $file )[ 0, 1 ] );
+    trace( 3, $file, ( stat $file )[ 0, 1 ] );
     return join( "/", ( stat $file )[ 0, 1 ] );
 }
 

src/Gitolite/Conf/Load.pm

@@ -192,7 +192,7 @@ sub load_1 {
     trace( 3, $repo );
 
     if ( repo_missing($repo) ) {
-        trace( 2, "repo '$repo' missing" );
+        trace( 1, "repo '$repo' missing" );
         return;
     }
     _chdir("$rc{GL_REPO_BASE}/$repo.git");

src/Gitolite/Conf/Store.pm

@@ -277,7 +277,7 @@ sub store_common {
     my $compiled_fh = _open( ">", "$cc.new" );
 
     my $data_version = glrc('current-data-version');
-    trace( 1, "data_version = $data_version" );
+    trace( 3, "data_version = $data_version" );
     print $compiled_fh Data::Dumper->Dump( [$data_version], [qw(*data_version)] );
 
     my $dumped_data = Data::Dumper->Dump( [ \%repos ], [qw(*repos)] );

src/Gitolite/Hooks/PostUpdate.pm

@@ -19,8 +19,7 @@ use warnings;
 # ----------------------------------------------------------------------
 
 sub post_update {
-    trace( 2, @ARGV );
+    trace( 1, 'post-up', @ARGV );
-    gl_log( 'post-up', @ARGV );
     # this is the *real* post_update hook for gitolite
 
     tsh_try("git ls-tree --name-only master");

src/Gitolite/Hooks/Update.pm

@@ -20,20 +20,20 @@ use warnings;
 # ----------------------------------------------------------------------
 
 sub update {
-    trace( 2, @ARGV );
-    gl_log( 'update', @ARGV );
     # this is the *real* update hook for gitolite
 
     my ( $ref, $oldsha, $newsha, $oldtree, $newtree, $aa ) = args(@ARGV);
 
+    trace( 1, 'update', $ENV{GL_REPO}, $ENV{GL_USER}, $aa, @ARGV );
+
     my $ret = access( $ENV{GL_REPO}, $ENV{GL_USER}, $aa, $ref );
-    trace( 1, "access($ENV{GL_REPO}, $ENV{GL_USER}, $aa, $ref)", "-> $ret" );
     trigger( 'ACCESS_2', $ENV{GL_REPO}, $ENV{GL_USER}, $aa, $ref, $ret );
     _die $ret if $ret =~ /DENIED/;
 
     check_vrefs( $ref, $oldsha, $newsha, $oldtree, $newtree, $aa );
 
-    gl_log( 'check2', $ENV{GL_REPO}, $ENV{GL_USER}, $aa, @ARGV, '->', $ret );
+    trace( 1, "-> $ret" );
+    gl_log( 'update', $ENV{GL_REPO}, $ENV{GL_USER}, $aa, @ARGV );
     exit 0;
 }
 
@@ -72,10 +72,10 @@ sub check_vref {
     my ( $aa, $ref, $deny_message ) = @_;
 
     my $ret = access( $ENV{GL_REPO}, $ENV{GL_USER}, $aa, $ref );
-    trace( 1, "access($ENV{GL_REPO}, $ENV{GL_USER}, $aa, $ref)", "-> $ret" );
+    trace( 2, "access($ENV{GL_REPO}, $ENV{GL_USER}, $aa, $ref)", "-> $ret" );
     _die "$ret" . ( $deny_message ? "\n$deny_message" : '' )
       if $ret =~ /DENIED/ and $ret !~ /by fallthru/;
-    trace( 1, "remember, fallthru is success here!" ) if $ret =~ /by fallthru/;
+    trace( 2, "remember, fallthru is success here!" ) if $ret =~ /by fallthru/;
 }
 
 {

src/Gitolite/Rc.pm

@@ -58,8 +58,7 @@ my $rc = glrc('filename');
 do $rc if -r $rc;
 if ( defined($GL_ADMINDIR) ) {
     say2 "";
-    say2 "FATAL: $rc seems to be for older gitolite; please see doc/g2migr.mkd\n" .
+    say2 "FATAL: $rc seems to be for older gitolite; please see doc/g2migr.mkd\n" . "(online at http://sitaramc.github.com/gitolite/g3/g2migr.html)";
-    "(online at http://sitaramc.github.com/gitolite/g3/g2migr.html)";
 
     exit 1;
 }
@@ -182,6 +181,7 @@ sub trigger {
                 if ( my ( $module, $sub ) = ( $pgm =~ /^(.*)::(\w+)$/ ) ) {
 
                     require Gitolite::Triggers;
+                    trace(1, 'trigger', $module, $sub, @args, $rc_section, @_ );
                     Gitolite::Triggers::run( $module, $sub, @args, $rc_section, @_ );
 
                 } else {
@@ -251,6 +251,9 @@ __DATA__
     UMASK                       =>  0077,
     GIT_CONFIG_KEYS             =>  '',
 
+    # comment out if you don't need all the extra detail in the logfile
+    LOG_EXTRA                   =>  1,
+
     # settings used by external programs; uncomment and change as needed.  You
     # can add your own variables for use in your own external programs; take a
     # look at the cpu-time and desc commands for perl and shell samples.

src/gitolite

@@ -46,7 +46,7 @@ use warnings;
 # ----------------------------------------------------------------------
 
 my ( $command, @args ) = @ARGV;
-gl_log( 'command', @ARGV ) if -d $rc{GL_ADMIN_BASE};
+gl_log( 'cli', 'gitolite', @ARGV ) if -d $rc{GL_ADMIN_BASE} and $$ == ( $ENV{GL_TID} || 0 );
 args();
 
 # the first two commands need options via @ARGV, as they have their own
@@ -91,7 +91,7 @@ if ( $command eq 'setup' ) {
     _die "unknown gitolite sub-command";
 }
 
-gl_log( '==end==' ) if $$ == $ENV{GL_TID};
+gl_log('END') if $$ == $ENV{GL_TID};
 
 sub args {
     usage() if not $command or $command eq '-h';

src/gitolite-shell

@@ -17,7 +17,7 @@ use warnings;
 # the main() sub expects ssh-ish things; set them up...
 my $id = '';
 if ( exists $ENV{G3T_USER} ) {
-    $id = in_local();    # file:// masquerading as ssh:// for easy testing
+    $id = in_file();    # file:// masquerading as ssh:// for easy testing
 } elsif ( exists $ENV{SSH_CONNECTION} ) {
     $id = in_ssh();
 } elsif ( exists $ENV{REQUEST_URI} ) {
@@ -28,18 +28,20 @@ if ( exists $ENV{G3T_USER} ) {
 
 main($id);
 
-gl_log( '==end==' ) if $$ == $ENV{GL_TID};
+gl_log('END') if $$ == $ENV{GL_TID};
 
 exit 0;
 
 # ----------------------------------------------------------------------
 
-sub in_local {
+sub in_file {
+    gl_log( 'file', "ARGV=" . join( ",", @ARGV ), "SOC=$ENV{SSH_ORIGINAL_COMMAND}" );
+
     if ( $ENV{SSH_ORIGINAL_COMMAND} =~ /git-\w+-pack/ ) {
         print STDERR "TRACE: gsh(", join( ")(", @ARGV ), ")\n";
         print STDERR "TRACE: gsh(SOC=$ENV{SSH_ORIGINAL_COMMAND})\n";
     }
-    return 'local';
+    return 'file';
 }
 
 sub in_http {
@@ -47,13 +49,16 @@ sub in_http {
 }
 
 sub in_ssh {
+    my $ip;
+    ( $ip = $ENV{SSH_CONNECTION} || '(no-IP)' ) =~ s/ .*//;
+
+    gl_log( 'ssh', "ARGV=" . join( ",", @ARGV ), "SOC=$ENV{SSH_ORIGINAL_COMMAND}", "FROM=$ip" );
+
     $ENV{SSH_ORIGINAL_COMMAND} ||= '';
     my $soc = $ENV{SSH_ORIGINAL_COMMAND};
     $soc =~ s/[\n\r]+/<<newline>>/g;
     _die "I don't like newlines in the command: $soc\n" if $ENV{SSH_ORIGINAL_COMMAND} ne $soc;
 
-    my $ip;
-    ($ip = $ENV{SSH_CONNECTION} || '(no-IP)') =~ s/ .*//;
     return $ip;
 }
 
@@ -64,7 +69,6 @@ sub in_ssh {
 sub main {
     my $id = shift;
 
-    gl_log( 'remote', $id, @ARGV, $ENV{SSH_ORIGINAL_COMMAND} );
     umask $rc{UMASK};
 
     # set up the user
@@ -91,9 +95,10 @@ sub main {
     unless ( $ENV{GL_BYPASS_ACCESS_CHECKS} ) {
         my $ret = access( $repo, $user, $aa, 'any' );
         trace( 1, "access($repo, $user, $aa, 'any')", "-> $ret" );
-        gl_log( 'check1', $repo, $user, $aa, 'any', '->', $ret );
         trigger( 'ACCESS_1', $repo, $user, $aa, 'any', $ret );
         _die $ret . "\n(or you mis-spelled the reponame)" if $ret =~ /DENIED/;
+
+        gl_log( "pre_git", $repo, $user, $aa, 'any', "-> $ret" );
     }
 
     trigger( 'PRE_GIT', $repo, $user, $aa, 'any', $verb );

t/0-me-first.t

@@ -53,7 +53,7 @@ try "
 
     # log file
     cat \$(gitolite query-rc GL_LOGFILE);
-                                    ok;     /check2/
+                                    ok;     /\tupdate\t/
                                             /aa\tu1\t\\+\trefs/heads/master/
                                             /2d066fb4860c29cf321170c17695c6883f3d50e8/
                                             /284951dfa11d58f99ab76b9f4e4c1ad2f2461236/