log message changes (warning: minor backward compat breakage)

The log message format has changed.  All log messages now have a common
prefix (timestamp, user, IP).  This is followed by $SSH_ORIGINAL_COMMAND
(or, in one special case, the name of the user's login shell).  Any
further text appears after this (currently this only happens in the case
of a successful push -- one for each ref pushed successfully)

doc/CHANGELOG

@@ -2,8 +2,12 @@ Major changes to gitolite, master branch only, most recent first, no dates but
 the tags can help you position stuff approximately
 [NYD = not yet documented due to lack of time...]
 
+  - v1.5.3
+
+  - log file format changed; minor backward compat breakage if you've been
+    doing any automated log processing
   - some small but important doc updates
-  - adc "fork" now much faster (uses git clone -l)
+  - adc "fork" now much faster and more space-efficient (uses git clone -l)
 
   - v1.5.2
 

hooks/common/update

@@ -105,9 +105,8 @@ my $log_refex = check_ref(\@allowed_refs, $ENV{GL_REPO}, (shift @refs), $att_acc
 
 # if we returned at all, all the checks succeeded, so we log the action and exit 0
 
-&log_it("$ENV{GL_TS}  $att_acc\t" .
-    substr($oldsha, 0, 14) . "\t" . substr($newsha, 0, 14) .
-    "\t$reported_repo\t$ref\t$ENV{GL_USER}\t$log_refex\n");
+&log_it("", "$att_acc\t" .  substr($oldsha, 0, 14) . "\t" . substr($newsha, 0, 14) .
+    "\t$reported_repo\t$ref\t$log_refex");
 
 # now chain to the local admin defined update hook, if present
 $UPDATE_CHAINS_TO ||= 'hooks/update.secondary';

src/gitolite.pm

@@ -58,8 +58,16 @@ sub wrap_open {
 }
 
 sub log_it {
+    my ($ip, $logmsg);
     open my $log_fh, ">>", $ENV{GL_LOG} or die "open log failed: $!\n";
-    print $log_fh @_;
+    # first space sep field is client ip, per "man ssh"
+    ($ip = $ENV{SSH_CONNECTION}) =~ s/ .*//;
+    # the first part of logmsg is the actual command used; it's either passed
+    # in via arg1, or picked up from SSH_ORIGINAL_COMMAND
+    $logmsg = $_[0] || $ENV{SSH_ORIGINAL_COMMAND}; shift;
+    # the rest of it upto the caller; we just dump it into the logfile
+    $logmsg .= "\t@_" if @_;
+    print $log_fh "$ENV{GL_TS}\t$ENV{GL_USER}\t$ip\t$logmsg\n";
     close $log_fh or die "close log failed: $!\n";
 }
 
@@ -474,7 +482,7 @@ sub special_cmd
         &ext_cmd_svnserve($SVNSERVE);
     } else {
         # if the user is allowed a shell, just run the command
-        &log_it("$ENV{GL_TS}\t$ENV{SSH_ORIGINAL_COMMAND}\t$ENV{GL_USER}\n");
+        &log_it();
         exec $ENV{SHELL}, "-c", $cmd if $shell_allowed;
 
         die "bad command: $cmd\n";
@@ -615,7 +623,7 @@ sub ext_cmd_rsync
         # that should "die" if there's a problem
 
     wrap_chdir($RSYNC_BASE);
-    &log_it("$ENV{GL_TS}\t$ENV{SSH_ORIGINAL_COMMAND}\t$ENV{GL_USER}\n");
+    &log_it();
     exec $ENV{SHELL}, "-c", $ENV{SSH_ORIGINAL_COMMAND};
 }
 

src/gl-auth-command

@@ -102,7 +102,7 @@ unless ($ENV{SSH_ORIGINAL_COMMAND}) {
     if ($shell_allowed) {
         my $shell = $ENV{SHELL};
         $shell =~ s/.*\//-/;    # change "/bin/bash" to "-bash"
-        &log_it("$ENV{GL_TS}\t$shell\t$user\n");
+        &log_it($shell);
         exec { $ENV{SHELL} } $shell;
     }
     # otherwise, pretend he typed in "info" and carry on...
@@ -119,7 +119,7 @@ if ($GL_ADC_PATH and -d $GL_ADC_PATH) {
     if (-x "$GL_ADC_PATH/$cmd") {
         # yes this is rather strict, sorry.
         do { die "I don't like $_\n" unless $_ =~ $REPOPATT_PATT } for ($cmd, @args);
-        &log_it("$ENV{GL_TS}\t$GL_ADC_PATH/$ENV{SSH_ORIGINAL_COMMAND}\t$ENV{GL_USER}\n");
+        &log_it("$GL_ADC_PATH/$ENV{SSH_ORIGINAL_COMMAND}");
         exec("$GL_ADC_PATH/$cmd", @args);
     }
 }
@@ -208,7 +208,7 @@ die "$aa access for $repo DENIED to $user\n" unless $perm =~ /$aa/;
 #       over to git now
 # ----------------------------------------------------------------------------
 
-&log_it("$ENV{GL_TS}\t$ENV{SSH_ORIGINAL_COMMAND}\t$ENV{GL_USER}\n");
+&log_it();
 
 $repo = "'$REPO_BASE/$repo.git'";
 exec("git", "shell", "-c", "$verb $repo") unless $verb eq 'git-init';

t/t00-initial

@@ -53,7 +53,7 @@ runlocal git push -f origin HEAD
 expect "+ .* HEAD -> master (forced update)"
 name "basic rewind log"
 taillog
-expect "\+.*aa.refs/heads/master.u1.refs/.\*"
+expect "	u1	.*	+	.*	aa	refs/heads/master	refs/.\*"
 
 # ----------
 name "basic rewind deny"