Write upload-pack metrics to sshd log

In order to enable detailed performance and problem analysis add
upload-pack metrics to the sshd log. The log format for upload-pack log
records is now enhanced to:
- timestamp
- session id
- thread name
- user name
- account id
- message
- command wait time
- command execution time
- time negotiating
- time searching for reuse
- time searching for sizes
- time counting
- time compressing
- time writing
- total time in UploadPack
- bitmap index misses (-1 means no bitmap index available)
- total deltas
- total objects
- total bytes transferred
- client agent

If statistics aren't available e.g. since an exception occurred they are
logged as -1.

Change-Id: I4ec08579cedfeb6a30eb41d2e2a110f4f8eee8fa

java/com/google/gerrit/sshd/BaseCommand.java

@@ -79,7 +79,7 @@ public abstract class BaseCommand implements Command {
   protected OutputStream out;
   protected OutputStream err;
 
-  private ExitCallback exit;
+  protected ExitCallback exit;
 
   @Inject protected CurrentUser user;
 
@@ -87,7 +87,7 @@ public abstract class BaseCommand implements Command {
 
   @Inject private CmdLineParser.Factory cmdLineParserFactory;
 
-  @Inject private RequestCleanup cleanup;
+  @Inject protected RequestCleanup cleanup;
 
   @Inject @CommandExecutor private ScheduledThreadPoolExecutor executor;
 

java/com/google/gerrit/sshd/CommandFactoryProvider.java

@@ -194,7 +194,7 @@ class CommandFactoryProvider implements Provider<CommandFactory>, LifecycleListe
                 @Override
                 public void onExit(int rc, String exitMessage) {
                   exit.onExit(translateExit(rc), exitMessage);
-                  log(rc);
+                  log(rc, exitMessage);
                 }
 
                 @Override
@@ -232,6 +232,12 @@ class CommandFactoryProvider implements Provider<CommandFactory>, LifecycleListe
       }
     }
 
+    private void log(int rc, String message) {
+      if (logged.compareAndSet(false, true)) {
+        log.onExecute(cmd, rc, ctx.getSession(), message);
+      }
+    }
+
     @Override
     public void destroy() {
       Future<?> future = task.getAndSet(null);

java/com/google/gerrit/sshd/SshLog.java

@@ -53,6 +53,7 @@ class SshLog implements LifecycleListener, GerritConfigListener {
   private static final String P_EXEC = "executionTime";
   private static final String P_STATUS = "status";
   private static final String P_AGENT = "agent";
+  private static final String P_MESSAGE = "message";
 
   private final Provider<SshSession> session;
   private final Provider<Context> context;
@@ -147,6 +148,10 @@ class SshLog implements LifecycleListener, GerritConfigListener {
   }
 
   void onExecute(DispatchCommand dcmd, int exitValue, SshSession sshSession) {
+    onExecute(dcmd, exitValue, sshSession, null);
+  }
+
+  void onExecute(DispatchCommand dcmd, int exitValue, SshSession sshSession, String message) {
     final Context ctx = context.get();
     ctx.finished = TimeUtil.nowMs();
 
@@ -180,6 +185,10 @@ class SshLog implements LifecycleListener, GerritConfigListener {
       event.setProperty(P_AGENT, peerAgent);
     }
 
+    if (message != null) {
+      event.setProperty(P_MESSAGE, message);
+    }
+
     if (async != null) {
       async.append(event);
     }

java/com/google/gerrit/sshd/SshLogLayout.java

@@ -30,6 +30,7 @@ public final class SshLogLayout extends Layout {
   private static final String P_EXEC = "executionTime";
   private static final String P_STATUS = "status";
   private static final String P_AGENT = "agent";
+  private static final String P_MESSAGE = "message";
 
   private final Calendar calendar;
   private long lastTimeMillis;
@@ -68,6 +69,7 @@ public final class SshLogLayout extends Layout {
 
     opt(P_WAIT, buf, event);
     opt(P_EXEC, buf, event);
+    opt(P_MESSAGE, buf, event);
     opt(P_STATUS, buf, event);
     opt(P_AGENT, buf, event);
 

java/com/google/gerrit/sshd/commands/Upload.java

@@ -31,6 +31,7 @@ import com.google.gerrit.sshd.SshSession;
 import com.google.inject.Inject;
 import java.io.IOException;
 import java.util.List;
+import org.eclipse.jgit.storage.pack.PackStatistics;
 import org.eclipse.jgit.transport.PostUploadHook;
 import org.eclipse.jgit.transport.PostUploadHookChain;
 import org.eclipse.jgit.transport.PreUploadHook;
@@ -47,6 +48,8 @@ final class Upload extends AbstractGitCommand {
   @Inject private SshSession session;
   @Inject private PermissionBackend permissionBackend;
 
+  private PackStatistics stats;
+
   @Override
   protected void runImpl() throws IOException, Failure {
     PermissionBackend.ForProject perm =
@@ -76,6 +79,7 @@ final class Upload extends AbstractGitCommand {
     try {
       up.upload(in, out, err);
       session.setPeerAgent(up.getPeerUserAgent());
+      stats = up.getStatistics();
     } catch (UploadValidationException e) {
       // UploadValidationException is used by the UploadValidators to
       // stop the uploadPack. We do not want this exception to go beyond this
@@ -86,4 +90,36 @@ final class Upload extends AbstractGitCommand {
       }
     }
   }
+
+  @Override
+  protected void onExit(int rc) {
+    exit.onExit(
+        rc,
+        stats != null
+            ? stats.getTimeNegotiating()
+                + "ms "
+                + stats.getTimeSearchingForReuse()
+                + "ms "
+                + stats.getTimeSearchingForSizes()
+                + "ms "
+                + stats.getTimeCounting()
+                + "ms "
+                + stats.getTimeCompressing()
+                + "ms "
+                + stats.getTimeWriting()
+                + "ms "
+                + stats.getTimeTotal()
+                + "ms "
+                + stats.getBitmapIndexMisses()
+                + " "
+                + stats.getTotalDeltas()
+                + " "
+                + stats.getTotalObjects()
+                + " "
+                + stats.getTotalBytes()
+            : "-1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1");
+    if (cleanup != null) {
+      cleanup.run();
+    }
+  }
 }