cleaned up logging quite a bit; details:

- a remote "id" (usually the IP) is generated and logged on the first
    log message in a "transaction"

  - speaking of which, a new "transaction ID" is logged that stays the
    same for each input command/invocation, tying together all the
    spawned commands

  - so now time stamps can be generated each time they are needed,
    rather than re-use the one at the beginning

  - log messages have a keyword at the start now
        remote, (create), check1 -- from gitolite-shell
        update, check2 -- from update
        post-up -- from post-update
        command -- from gitolite
        die, system -- from anywhere

src/Gitolite/Common.pm

@@ -10,7 +10,7 @@ package Gitolite::Common;
   say2    _die    _system slurp             tsh_lines
           trace           cleanup_conf_line tsh_try
           usage                             tsh_run
-          gen_ts_lfn
+          gen_lfn
           gl_log
 );
 #>>>
@@ -72,7 +72,7 @@ sub _warn {
 }
 
 sub _die {
-    gl_log( "_die:", @_ );
+    gl_log( 'die', @_ );
     if ( $ENV{D} and $ENV{D} >= 3 ) {
         confess "FATAL: " . join( ",", @_ ) . "\n" if defined( $ENV{D} );
     } elsif ( defined( $ENV{D} ) ) {
@@ -112,7 +112,7 @@ 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, @_ );
-    gl_log( "_system:", @_ );
+    gl_log( 'system', @_ );
     if ( system(@_) != 0 ) {
         trace( 1, "system() failed", @_, "-> $?" );
         if ( $? == -1 ) {
@@ -205,9 +205,8 @@ sub cleanup_conf_line {
     }
 }
 
-# generate a timestamp.  If a template is passed generate a log file name
+# generate a timestamp
-# based on it also
+sub gen_ts {
-sub gen_ts_lfn {
     my ( $s, $min, $h, $d, $m, $y ) = (localtime)[ 0 .. 5 ];
     $y += 1900; $m++;    # usual adjustments
     for ( $s, $min, $h, $d, $m ) {
@@ -215,7 +214,16 @@ sub gen_ts_lfn {
     }
     my $ts = "$y-$m-$d.$h:$min:$s";
 
-    return $ts unless @_;
+    return $ts;
+}
+
+# generate a log file name
+sub gen_lfn {
+    my ( $s, $min, $h, $d, $m, $y ) = (localtime)[ 0 .. 5 ];
+    $y += 1900; $m++;    # usual adjustments
+    for ( $s, $min, $h, $d, $m ) {
+        $_ = "0$_" if $_ < 10;
+    }
 
     my ($template) = shift;
     # substitute template parameters and set the logfile name
@@ -223,7 +231,7 @@ sub gen_ts_lfn {
     $template =~ s/%m/$m/g;
     $template =~ s/%d/$d/g;
 
-    return ( $ts, $template );
+    return $template;
 }
 
 sub gl_log {
@@ -231,13 +239,15 @@ sub gl_log {
     # called even before they are set, we have no choice but to dump to STDERR
     # (and probably call "logger").
     my $msg = join( "\t", @_ );
+    $msg =~ s/[\n\r]+/<<newline>>/g;
 
-    my $ts = $ENV{GL_TS} || gen_ts_lfn();
+    my $ts  = gen_ts();
+    my $tid = $ENV{GL_TID} ||= $$;
 
     my $fh;
     logger_plus_stderr( "$ts no GL_LOGFILE env var", "$ts $msg" ) if not $ENV{GL_LOGFILE};
     open my $lfh, ">>", $ENV{GL_LOGFILE} or logger_plus_stderr( "open log failed: $!", $msg );
-    print $lfh "$ts\t$msg\n";
+    print $lfh "$ts\t$tid\t$msg\n";
     close $lfh;
 }
 

src/Gitolite/Hooks/PostUpdate.pm

@@ -20,7 +20,7 @@ use warnings;
 
 sub post_update {
     trace( 2, @ARGV );
-    gl_log( 'post-update', @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

@@ -28,20 +28,21 @@ sub update {
 
     my $ret = access( $ENV{GL_REPO}, $ENV{GL_USER}, $aa, $ref );
     trace( 1, "access($ENV{GL_REPO}, $ENV{GL_USER}, $aa, $ref)", "-> $ret" );
-    gl_log( 'update:check', $ENV{GL_REPO}, $ENV{GL_USER}, $aa, $ref, '->', $ret );
     trigger( 'ACCESS_CHECK', $ENV{GL_REPO}, $ENV{GL_USER}, $aa, $ref, $ret );
     _die $ret if $ret =~ /DENIED/;
 
     check_vrefs( $ref, $oldsha, $newsha, $oldtree, $newtree, $aa );
-    gl_log( 'update:OK', $ENV{GL_REPO}, $ENV{GL_USER}, $aa, @ARGV );
 
+    gl_log( 'check2', $ENV{GL_REPO}, $ENV{GL_USER}, $aa, @ARGV, '->', $ret );
     exit 0;
 }
 
 sub check_vrefs {
     my ( $ref, $oldsha, $newsha, $oldtree, $newtree, $aa ) = @_;
     my $name_seen = 0;
+    my $n_vrefs = 0;
     for my $vref ( vrefs( $ENV{GL_REPO}, $ENV{GL_USER} ) ) {
+        $n_vrefs++;
         if ( $vref =~ m(^VREF/NAME/) ) {
             # this one is special; we process it right here, and only once
             next if $name_seen++;
@@ -64,6 +65,7 @@ sub check_vrefs {
               : "$vref: helper program exit status $?";
         }
     }
+    return $n_vrefs;
 }
 
 sub check_vref {

src/Gitolite/Rc.pm

@@ -72,9 +72,12 @@ do $ENV{G3T_RC} if exists $ENV{G3T_RC} and -r $ENV{G3T_RC};
 $ENV{PATH} = "$ENV{GL_BINDIR}:$ENV{PATH}";
 
 {
-    my ( $ts, $lfn ) = gen_ts_lfn( $rc{LOG_TEMPLATE} );
+    $rc{GL_TID} = $ENV{GL_TID} ||= $$;
-    $rc{GL_LOGFILE} = $ENV{GL_LOGFILE} = $lfn;
+    # TID: loosely, transaction ID.  The first PID at the entry point passes
-    $rc{GL_TS}      = $ENV{GL_TS}      = $ts;
+    # it down to all its children so you can track each access, across all the
+    # various commands it spawns and actions it generates.
+
+    $rc{GL_LOGFILE} = $ENV{GL_LOGFILE} ||= gen_lfn( $rc{LOG_TEMPLATE} );
 }
 
 # these two are meant to help externally written commands (see

src/gitolite

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

src/gitolite-shell

@@ -15,17 +15,20 @@ use strict;
 use warnings;
 
 # the main() sub expects ssh-ish things; set them up...
+my $id = '';
 if ( exists $ENV{G3T_USER} ) {
-    in_local();    # file:// masquerading as ssh:// for easy testing
+    $id = in_local();    # file:// masquerading as ssh:// for easy testing
 } elsif ( exists $ENV{SSH_CONNECTION} ) {
-    in_ssh();
+    $id = in_ssh();
 } elsif ( exists $ENV{REQUEST_URI} ) {
-    in_http();
+    $id = in_http();
 } else {
     _die "who the *heck* are you?";
 }
 
-main();
+main($id);
+
+gl_log( '==end==' ) if $$ == $ENV{GL_TID};
 
 exit 0;
 
@@ -38,6 +41,7 @@ sub in_local {
         print STDERR "TRACE: gsh(", join( ")(", @ARGV ), ")\n";
         print STDERR "TRACE: gsh(SOC=$ENV{SSH_ORIGINAL_COMMAND})\n";
     }
+    return 'local';
 }
 
 sub in_http {
@@ -49,6 +53,10 @@ sub in_ssh {
     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;
 }
 
 # ----------------------------------------------------------------------
@@ -56,7 +64,9 @@ sub in_ssh {
 # call this once you are sure arg-1 is the username and SSH_ORIGINAL_COMMAND
 # has been setup (even if it's not actually coming via ssh).
 sub main {
-    gl_log( 'gitolite-shell', @ARGV, $ENV{SSH_ORIGINAL_COMMAND} );
+    my $id = shift;
+
+    gl_log( 'remote', $id, @ARGV, $ENV{SSH_ORIGINAL_COMMAND} );
     umask $rc{UMASK};
 
     # set up the user
@@ -73,7 +83,7 @@ sub main {
         require Gitolite::Conf::Store;
         Gitolite::Conf::Store->import;
         new_wild_repo( $repo, $user );
-        gl_log( 'gitolite-shell:new_wild_repo', $repo, $user );
+        gl_log( 'create', $repo, $user );
     }
 
     # a ref of 'any' signifies that this is a pre-git check, where we don't
@@ -82,9 +92,9 @@ sub main {
     # more information.
     my $ret = access( $repo, $user, $aa, 'any' );
     trace( 1, "access($repo, $user, $aa, 'any')", "-> $ret" );
-    gl_log( 'gitolite-shell:check', $repo, $user, $aa, 'any', '->', $ret );
+    gl_log( 'check1', $repo, $user, $aa, 'any', '->', $ret );
     trigger( 'ACCESS_CHECK', $repo, $user, $aa, 'any', $ret );
-    _die $ret if $ret =~ /DENIED/;
+    _die $ret . "\n(or you mis-spelled the reponame)" if $ret =~ /DENIED/;
 
     check_repo_write_enabled($repo) if $aa eq 'W';
     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;     /update:OK/
+                                    ok;     /check2/
                                             /aa\tu1\t\\+\trefs/heads/master/
                                             /2d066fb4860c29cf321170c17695c6883f3d50e8/
                                             /284951dfa11d58f99ab76b9f4e4c1ad2f2461236/