Log SSH activity to $site_path/logs/sshd_log

The sshd_log now records authentication failure, login, logout and
command execution.  Example run:

  [2009-12-29 10:22:35,581 -0800] bd6b094b root - AUTH FAILURE FROM 127.0.0.1 user-not-found
  [2009-12-29 10:29:21,979 -0800] 5d60cd6e spearce a/1001240 LOGIN FROM 127.0.0.1
  [2009-12-29 10:29:47,994 -0800] 5d60cd6e spearce a/1001240 'git-upload-pack tools/repo.git' 3ms 42ms 0
  [2009-12-29 10:29:52,533 -0800] 5d60cd6e spearce a/1001240 'git-upload-pack tools/gerrit.git' 2ms 321ms 0
  [2009-12-29 10:29:56,702 -0800] 5d60cd6e spearce a/1001240 LOGOUT

Log lines are formatted into fields as follows:

  * date and time
  * unique session identifier
  * username
  * internal account id
  * command name
  * milliseconds spent waiting for execution thread
  * milliseconds spent executing command
  * exit status

The unique session identifier can be used to string together commands
which came over the same SSH connection.  To produce the above log
output I ran in one terminal window:

  $ ssh -o 'ControlPath /tmp/me.sock' -p 29418 -M -N spearce@localhost

to establish the session, and then in another window:

  $ ssh -o 'ControlPath /tmp/me.sock' -p 29418 spearce@localhost git-upload-pack tools/repo.git </dev/null
  $ ssh -o 'ControlPath /tmp/me.sock' -p 29418 spearce@localhost git-upload-pack tools/gerrit.git </dev/null

to perform two commands on the same existing session, and therefore
the same session identity 5d60cd6e is used on all messages.

To improve performance during request processing, login and
authentication failure lines never perform a reverse hostname lookup.
Only the IP address of the remote peer is stored in the log file.

Log messages are written to disk through a background thread,
so execution threads can work without being blocked on the local
disk log.  A bounded queue of 64 log events is used in memory to
throttle the execution threads, if the log thread gets behind by
more than 64 events the execution threads will stall until there
is sufficient buffer space available.

Log files are rotated daily, and compressed automatically when the
error_log is compressed, if run through our daemon command.

Change-Id: Ibeae49fac80f4ca7d24db0de24a43642e0fe92ab
Signed-off-by: Shawn O. Pearce <sop@google.com>

gerrit-pgm/src/main/java/com/google/gerrit/pgm/util/LogFileCompressor.java

@@ -97,6 +97,7 @@ public class LogFileCompressor implements Runnable {
   private boolean isLive(final File entry) {
     final String name = entry.getName();
     return ErrorLogFile.LOG_NAME.equals(name) //
+        || "sshd_log".equals(name) //
         || name.endsWith(".pid");
   }
 

gerrit-sshd/pom.xml

@@ -33,6 +33,11 @@ limitations under the License.
   </description>
 
   <dependencies>
+    <dependency>
+      <groupId>log4j</groupId>
+      <artifactId>log4j</artifactId>
+    </dependency>
+
     <dependency>
       <groupId>org.eclipse.jgit</groupId>
       <artifactId>org.eclipse.jgit.junit</artifactId>

gerrit-sshd/src/main/java/com/google/gerrit/sshd/BaseCommand.java

@@ -50,6 +50,11 @@ public abstract class BaseCommand implements Command {
   private static final Logger log = LoggerFactory.getLogger(BaseCommand.class);
   public static final String ENC = "UTF-8";
 
+  private static final int PRIVATE_STATUS = 1 << 30;
+  static final int STATUS_CANCEL = PRIVATE_STATUS | 1;
+  static final int STATUS_NOT_FOUND = PRIVATE_STATUS | 2;
+  static final int STATUS_NOT_ADMIN = PRIVATE_STATUS | 3;
+
   @Option(name = "--help", usage = "display this help text", aliases = {"-h"})
   private boolean help;
 
@@ -381,7 +386,7 @@ public abstract class BaseCommand implements Command {
     public void cancel() {
       try {
         SshScopes.current.set(context);
-        onExit(15);
+        onExit(STATUS_CANCEL);
       } finally {
         SshScopes.current.set(null);
       }
@@ -393,6 +398,7 @@ public abstract class BaseCommand implements Command {
       final String thisName = thisThread.getName();
       int rc = 0;
       try {
+        context.started = System.currentTimeMillis();
         thisThread.setName("SSH " + toString());
         SshScopes.current.set(context);
         try {

gerrit-sshd/src/main/java/com/google/gerrit/sshd/CommandFactoryProvider.java

@@ -34,11 +34,14 @@ import java.io.OutputStream;
  */
 class CommandFactoryProvider implements Provider<CommandFactory> {
   private final DispatchCommandProvider dispatcher;
+  private final SshLog log;
 
   @Inject
   CommandFactoryProvider(
-      @CommandName(Commands.ROOT) final DispatchCommandProvider d) {
+      @CommandName(Commands.ROOT) final DispatchCommandProvider d,
+      final SshLog l) {
     dispatcher = d;
+    log = l;
   }
 
   @Override
@@ -59,6 +62,7 @@ class CommandFactoryProvider implements Provider<CommandFactory> {
     private ServerSession session;
     private Context ctx;
     private DispatchCommand cmd;
+    private boolean logged;
 
     Trampoline(final String cmdLine) {
       commandLine = cmdLine;
@@ -96,7 +100,19 @@ class CommandFactoryProvider implements Provider<CommandFactory> {
           cmd.setInputStream(in);
           cmd.setOutputStream(out);
           cmd.setErrorStream(err);
-          cmd.setExitCallback(exit);
+          cmd.setExitCallback(new ExitCallback() {
+            @Override
+            public void onExit(int rc, String exitMessage) {
+              exit.onExit(translateExit(rc), exitMessage);
+              log(rc);
+            }
+
+            @Override
+            public void onExit(int rc) {
+              exit.onExit(translateExit(rc));
+              log(rc);
+            }
+          });
           cmd.start(env);
         } finally {
           SshScopes.current.set(old);
@@ -104,6 +120,32 @@ class CommandFactoryProvider implements Provider<CommandFactory> {
       }
     }
 
+    private int translateExit(final int rc) {
+      switch (rc) {
+        case BaseCommand.STATUS_NOT_ADMIN:
+          return 1;
+
+        case BaseCommand.STATUS_CANCEL:
+          return 15 /* SIGKILL */;
+
+        case BaseCommand.STATUS_NOT_FOUND:
+          return 127 /* POSIX not found */;
+
+        default:
+          return rc;
+      }
+    }
+
+    private void log(final int rc) {
+      synchronized (this) {
+        if (!logged) {
+          ctx.finished = System.currentTimeMillis();
+          log.onExecute(ctx, commandLine, rc);
+          logged = true;
+        }
+      }
+    }
+
     @Override
     public void destroy() {
       synchronized (this) {
@@ -112,6 +154,7 @@ class CommandFactoryProvider implements Provider<CommandFactory> {
           try {
             SshScopes.current.set(ctx);
             cmd.destroy();
+            log(BaseCommand.STATUS_CANCEL);
           } finally {
             ctx = null;
             cmd = null;

gerrit-sshd/src/main/java/com/google/gerrit/sshd/DatabasePubKeyAuth.java

@@ -14,10 +14,17 @@
 
 package com.google.gerrit.sshd;
 
+import static com.google.gerrit.sshd.SshUtil.AUTH_ATTEMPTED_AS;
+import static com.google.gerrit.sshd.SshUtil.AUTH_ERROR;
+import static com.google.gerrit.sshd.SshUtil.CURRENT_ACCOUNT;
+
 import com.google.gerrit.reviewdb.AccountSshKey;
+import com.google.gerrit.sshd.SshScopes.Context;
 import com.google.inject.Inject;
 import com.google.inject.Singleton;
 
+import org.apache.mina.core.future.IoFuture;
+import org.apache.mina.core.future.IoFutureListener;
 import org.apache.sshd.server.PublickeyAuthenticator;
 import org.apache.sshd.server.session.ServerSession;
 
@@ -33,10 +40,12 @@ import java.security.PublicKey;
 @Singleton
 class DatabasePubKeyAuth implements PublickeyAuthenticator {
   private final SshKeyCacheImpl sshKeyCache;
+  private final SshLog log;
 
   @Inject
-  DatabasePubKeyAuth(final SshKeyCacheImpl skc) {
+  DatabasePubKeyAuth(final SshKeyCacheImpl skc, final SshLog l) {
     sshKeyCache = skc;
+    log = l;
   }
 
   public boolean authenticate(final String username,
@@ -44,7 +53,15 @@ class DatabasePubKeyAuth implements PublickeyAuthenticator {
     final Iterable<SshKeyCacheEntry> keyList = sshKeyCache.get(username);
     final SshKeyCacheEntry key = find(keyList, suppliedKey);
     if (key == null) {
-      return false;
+      final String err;
+      if (keyList == SshKeyCacheImpl.NO_SUCH_USER) {
+        err = "user-not-found";
+      } else if (keyList == SshKeyCacheImpl.NO_KEYS) {
+        err = "key-list-empty";
+      } else {
+        err = "no-matching-key";
+      }
+      return fail(username, session, err);
     }
 
     // Double check that all of the keys are for the same user account.
@@ -55,14 +72,49 @@ class DatabasePubKeyAuth implements PublickeyAuthenticator {
     //
     for (final SshKeyCacheEntry otherKey : keyList) {
       if (!key.getAccount().equals(otherKey.getAccount())) {
-        return false;
+        return fail(username, session, "keys-cross-accounts");
       }
     }
 
-    session.setAttribute(SshUtil.CURRENT_ACCOUNT, key.getAccount());
+    if (session.setAttribute(CURRENT_ACCOUNT, key.getAccount()) == null) {
+      // If this is the first time we've authenticated this
+      // session, record a login event in the log and add
+      // a close listener to record a logout event.
+      //
+      final Context ctx = new Context(session);
+      final Context old = SshScopes.current.get();
+      try {
+        SshScopes.current.set(ctx);
+        log.onLogin();
+      } finally {
+        SshScopes.current.set(old);
+      }
+
+      session.getIoSession().getCloseFuture().addListener(
+          new IoFutureListener<IoFuture>() {
+            @Override
+            public void operationComplete(IoFuture future) {
+              final Context old = SshScopes.current.get();
+              try {
+                SshScopes.current.set(ctx);
+                log.onLogout();
+              } finally {
+                SshScopes.current.set(old);
+              }
+            }
+          });
+    }
+
     return true;
   }
 
+  private static boolean fail(final String username,
+      final ServerSession session, final String err) {
+    session.setAttribute(AUTH_ATTEMPTED_AS, username);
+    session.setAttribute(AUTH_ERROR, err);
+    return false;
+  }
+
   private SshKeyCacheEntry find(final Iterable<SshKeyCacheEntry> keyList,
       final PublicKey suppliedKey) {
     for (final SshKeyCacheEntry k : keyList) {

gerrit-sshd/src/main/java/com/google/gerrit/sshd/DispatchCommand.java

@@ -79,7 +79,7 @@ final class DispatchCommand extends BaseCommand {
         if (!u.isAdministrator()) {
           err.write("fatal: Not a Gerrit administrator\n".getBytes(ENC));
           err.flush();
-          onExit(1);
+          onExit(BaseCommand.STATUS_NOT_ADMIN);
           return;
         }
       }
@@ -98,7 +98,7 @@ final class DispatchCommand extends BaseCommand {
       final String msg = prefix + ": " + name + ": not found\n";
       err.write(msg.getBytes(ENC));
       err.flush();
-      onExit(127);
+      onExit(BaseCommand.STATUS_NOT_FOUND);
     }
   }
 

gerrit-sshd/src/main/java/com/google/gerrit/sshd/SshDaemon.java

@@ -26,6 +26,8 @@ import com.google.inject.Singleton;
 import com.jcraft.jsch.HostKey;
 import com.jcraft.jsch.JSchException;
 
+import org.apache.mina.core.future.IoFuture;
+import org.apache.mina.core.future.IoFutureListener;
 import org.apache.mina.core.service.IoAcceptor;
 import org.apache.mina.core.session.IoSession;
 import org.apache.mina.transport.socket.SocketSessionConfig;
@@ -119,7 +121,7 @@ public class SshDaemon extends SshServer implements SshInfo, LifecycleListener {
   SshDaemon(final CommandFactory commandFactory,
       final PublickeyAuthenticator userAuth,
       final KeyPairProvider hostKeyProvider, final IdGenerator idGenerator,
-      @GerritServerConfig final Config cfg) {
+      @GerritServerConfig final Config cfg, final SshLog sshLog) {
     setPort(IANA_SSH_PORT /* never used */);
 
     listen = parseListen(cfg);
@@ -155,6 +157,20 @@ public class SshDaemon extends SshServer implements SshInfo, LifecycleListener {
         s.setAttribute(SshUtil.REMOTE_PEER, io.getRemoteAddress());
         s.setAttribute(SshUtil.SESSION_ID, idGenerator.next());
         s.setAttribute(SshScopes.sessionMap, new HashMap<Key<?>, Object>());
+
+        // Log a session close without authentication as a failure.
+        //
+        io.getCloseFuture().addListener(new IoFutureListener<IoFuture>() {
+          @Override
+          public void operationComplete(IoFuture future) {
+            if (s.getUsername() == null /* not authenticated */) {
+              String username = s.getAttribute(SshUtil.AUTH_ATTEMPTED_AS);
+              if (username != null) {
+                sshLog.onAuthFail(s, username);
+              }
+            }
+          }
+        });
         return s;
       }
     });

gerrit-sshd/src/main/java/com/google/gerrit/sshd/SshKeyCacheImpl.java

@@ -37,6 +37,7 @@ import java.security.NoSuchAlgorithmException;
 import java.security.NoSuchProviderException;
 import java.security.spec.InvalidKeySpecException;
 import java.util.ArrayList;
+import java.util.Arrays;
 import java.util.Collections;
 import java.util.List;
 
@@ -47,6 +48,9 @@ public class SshKeyCacheImpl implements SshKeyCache {
       LoggerFactory.getLogger(SshKeyCacheImpl.class);
   private static final String CACHE_NAME = "sshkeys";
 
+  static final Iterable<SshKeyCacheEntry> NO_SUCH_USER = none();
+  static final Iterable<SshKeyCacheEntry> NO_KEYS = none();
+
   public static Module module() {
     return new CacheModule() {
       @Override
@@ -60,6 +64,11 @@ public class SshKeyCacheImpl implements SshKeyCache {
     };
   }
 
+  private static Iterable<SshKeyCacheEntry> none() {
+    return Collections.unmodifiableCollection(Arrays
+        .asList(new SshKeyCacheEntry[0]));
+  }
+
   private final SchemaFactory<ReviewDb> schema;
   private final SelfPopulatingCache<String, Iterable<SshKeyCacheEntry>> self;
 
@@ -115,7 +124,7 @@ public class SshKeyCacheImpl implements SshKeyCache {
     try {
       final Account user = db.accounts().bySshUserName(username);
       if (user == null) {
-        return Collections.<SshKeyCacheEntry> emptyList();
+        return NO_SUCH_USER;
       }
 
       final List<SshKeyCacheEntry> kl = new ArrayList<SshKeyCacheEntry>(4);
@@ -123,7 +132,7 @@ public class SshKeyCacheImpl implements SshKeyCache {
         add(db, kl, k);
       }
       if (kl.isEmpty()) {
-        return Collections.<SshKeyCacheEntry> emptyList();
+        return NO_KEYS;
       }
       return Collections.unmodifiableList(kl);
     } finally {

gerrit-sshd/src/main/java/com/google/gerrit/sshd/SshLog.java

@@ -0,0 +1,402 @@
+// Copyright (C) 2009 The Android Open Source Project
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+// http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+package com.google.gerrit.sshd;
+
+import com.google.gerrit.lifecycle.LifecycleListener;
+import com.google.gerrit.server.IdentifiedUser;
+import com.google.gerrit.server.config.SitePaths;
+import com.google.gerrit.server.util.IdGenerator;
+import com.google.gerrit.sshd.SshScopes.Context;
+import com.google.inject.Inject;
+import com.google.inject.Provider;
+import com.google.inject.Singleton;
+
+import org.apache.log4j.Appender;
+import org.apache.log4j.AsyncAppender;
+import org.apache.log4j.DailyRollingFileAppender;
+import org.apache.log4j.Layout;
+import org.apache.log4j.Level;
+import org.apache.log4j.Logger;
+import org.apache.log4j.spi.ErrorHandler;
+import org.apache.log4j.spi.LoggingEvent;
+import org.apache.sshd.server.session.ServerSession;
+import org.eclipse.jgit.util.QuotedString;
+
+import java.io.File;
+import java.io.IOException;
+import java.net.InetAddress;
+import java.net.InetSocketAddress;
+import java.net.SocketAddress;
+import java.text.SimpleDateFormat;
+import java.util.Calendar;
+import java.util.Date;
+import java.util.TimeZone;
+
+@Singleton
+class SshLog implements LifecycleListener {
+  private static final Logger log = Logger.getLogger(SshLog.class);
+  private static final String LOG_NAME = "sshd_log";
+  private static final String P_SESSION = "session";
+  private static final String P_USER_NAME = "userName";
+  private static final String P_ACCOUNT_ID = "accountId";
+  private static final String P_WAIT = "queueWaitTime";
+  private static final String P_EXEC = "executionTime";
+  private static final String P_STATUS = "status";
+
+  private final Provider<ServerSession> session;
+  private final Provider<IdentifiedUser> user;
+  private final AsyncAppender async;
+
+  @Inject
+  SshLog(final Provider<ServerSession> session,
+      final Provider<IdentifiedUser> user, final SitePaths site) {
+    this.session = session;
+    this.user = user;
+
+    final DailyRollingFileAppender dst = new DailyRollingFileAppender();
+    dst.setName(LOG_NAME);
+    dst.setLayout(new MyLayout());
+    dst.setEncoding("UTF-8");
+    dst.setFile(new File(resolve(site.logs_dir), LOG_NAME).getPath());
+    dst.setImmediateFlush(true);
+    dst.setAppend(true);
+    dst.setThreshold(Level.INFO);
+    dst.setErrorHandler(new DieErrorHandler());
+    dst.activateOptions();
+    dst.setErrorHandler(new LogLogHandler());
+
+    async = new AsyncAppender();
+    async.setBlocking(true);
+    async.setBufferSize(64);
+    async.setLocationInfo(false);
+    async.addAppender(dst);
+    async.activateOptions();
+  }
+
+  @Override
+  public void start() {
+  }
+
+  @Override
+  public void stop() {
+    async.close();
+  }
+
+  void onLogin() {
+    final ServerSession s = session.get();
+    final SocketAddress addr = s.getIoSession().getRemoteAddress();
+    async.append(log("LOGIN FROM " + format(addr)));
+  }
+
+  void onAuthFail(final ServerSession s, final String username) {
+    final SocketAddress addr = s.getIoSession().getRemoteAddress();
+
+    final LoggingEvent event = new LoggingEvent( //
+        Logger.class.getName(), // fqnOfCategoryClass
+        null, // logger (optional)
+        System.currentTimeMillis(), // when
+        Level.INFO, // level
+        "AUTH FAILURE FROM " + format(addr), // message text
+        "SSHD", // thread name
+        null, // exception information
+        null, // current NDC string
+        null, // caller location
+        null // MDC properties
+        );
+
+    event.setProperty(P_SESSION, id(s.getAttribute(SshUtil.SESSION_ID)));
+    event.setProperty(P_USER_NAME, username);
+
+    final String error = s.getAttribute(SshUtil.AUTH_ERROR);
+    if (error != null) {
+      event.setProperty(P_STATUS, error);
+    }
+
+    async.append(event);
+  }
+
+  void onExecute(final Context ctx, final String commandLine, int exitValue) {
+    String cmd = QuotedString.BOURNE.quote(commandLine);
+    if (cmd == commandLine) {
+      cmd = "'" + commandLine + "'";
+    }
+
+    final LoggingEvent event = log(cmd);
+    event.setProperty(P_WAIT, (ctx.started - ctx.created) + "ms");
+    event.setProperty(P_EXEC, (ctx.finished - ctx.started) + "ms");
+
+    final String status;
+    switch (exitValue) {
+      case BaseCommand.STATUS_CANCEL:
+        status = "killed";
+        break;
+
+      case BaseCommand.STATUS_NOT_FOUND:
+        status = "not-found";
+        break;
+
+      case BaseCommand.STATUS_NOT_ADMIN:
+        status = "not-admin";
+        break;
+
+      default:
+        status = String.valueOf(exitValue);
+        break;
+    }
+    event.setProperty(P_STATUS, status);
+
+    async.append(event);
+  }
+
+  void onLogout() {
+    async.append(log("LOGOUT"));
+  }
+
+  private LoggingEvent log(final String msg) {
+    final ServerSession s = session.get();
+    final IdentifiedUser u = user.get();
+
+    final LoggingEvent event = new LoggingEvent( //
+        Logger.class.getName(), // fqnOfCategoryClass
+        null, // logger (optional)
+        System.currentTimeMillis(), // when
+        Level.INFO, // level
+        msg, // message text
+        "SSHD", // thread name
+        null, // exception information
+        null, // current NDC string
+        null, // caller location
+        null // MDC properties
+        );
+
+    event.setProperty(P_SESSION, id(s.getAttribute(SshUtil.SESSION_ID)));
+    event.setProperty(P_USER_NAME, u.getAccount().getSshUserName());
+    event.setProperty(P_ACCOUNT_ID, "a/" + u.getAccountId().toString());
+
+    return event;
+  }
+
+  private static String format(final SocketAddress remote) {
+    if (remote instanceof InetSocketAddress) {
+      final InetSocketAddress sa = (InetSocketAddress) remote;
+
+      final InetAddress in = sa.getAddress();
+      if (in != null) {
+        return in.getHostAddress();
+      }
+
+      final String hostName = sa.getHostName();
+      if (hostName != null) {
+        return hostName;
+      }
+    }
+    return remote.toString();
+  }
+
+  private static String id(final Integer id) {
+    return id != null ? IdGenerator.format(id) : "";
+  }
+
+  private static File resolve(final File logs_dir) {
+    try {
+      return logs_dir.getCanonicalFile();
+    } catch (IOException e) {
+      return logs_dir.getAbsoluteFile();
+    }
+  }
+
+  private static final class MyLayout extends Layout {
+    private final Calendar calendar;
+    private long lastTimeMillis;
+    private final char[] lastTimeString = new char[20];
+    private final char[] timeZone;
+
+    MyLayout() {
+      final TimeZone tz = TimeZone.getDefault();
+      calendar = Calendar.getInstance(tz);
+
+      final SimpleDateFormat sdf = new SimpleDateFormat("Z");
+      sdf.setTimeZone(tz);
+      timeZone = sdf.format(new Date()).toCharArray();
+    }
+
+    @Override
+    public String format(LoggingEvent event) {
+      final StringBuffer buf = new StringBuffer(128);
+
+      buf.append('[');
+      formatDate(event.getTimeStamp(), buf);
+      buf.append(' ');
+      buf.append(timeZone);
+      buf.append(']');
+
+      req(P_SESSION, buf, event);
+      req(P_USER_NAME, buf, event);
+      req(P_ACCOUNT_ID, buf, event);
+
+      buf.append(' ');
+      buf.append(event.getMessage());
+
+      opt(P_WAIT, buf, event);
+      opt(P_EXEC, buf, event);
+      opt(P_STATUS, buf, event);
+
+      buf.append('\n');
+      return buf.toString();
+    }
+
+    private void formatDate(final long now, final StringBuffer sbuf) {
+      final int millis = (int) (now % 1000);
+      final long rounded = now - millis;
+      if (rounded != lastTimeMillis) {
+        synchronized (calendar) {
+          final int start = sbuf.length();
+
+          calendar.setTimeInMillis(rounded);
+          sbuf.append(calendar.get(Calendar.YEAR));
+          sbuf.append('-');
+          final int month = calendar.get(Calendar.MONTH) + 1;
+          if (month < 10) sbuf.append('0');
+          sbuf.append(month);
+          sbuf.append('-');
+          final int day = calendar.get(Calendar.DAY_OF_MONTH);
+          if (day < 10) sbuf.append('0');
+          sbuf.append(day);
+
+          sbuf.append(' ');
+          final int hour = calendar.get(Calendar.HOUR_OF_DAY);
+          if (hour < 10) sbuf.append('0');
+          sbuf.append(hour);
+          sbuf.append(':');
+          final int mins = calendar.get(Calendar.MINUTE);
+          if (mins < 10) sbuf.append('0');
+          sbuf.append(mins);
+          sbuf.append(':');
+          final int secs = calendar.get(Calendar.SECOND);
+          if (secs < 10) sbuf.append('0');
+          sbuf.append(secs);
+
+          sbuf.append(',');
+          sbuf.getChars(start, sbuf.length(), lastTimeString, 0);
+          lastTimeMillis = rounded;
+        }
+      } else {
+        sbuf.append(lastTimeString);
+      }
+      if (millis < 100) {
+        sbuf.append('0');
+      }
+      if (millis < 10) {
+        sbuf.append('0');
+      }
+      sbuf.append(millis);
+    }
+
+    private void req(String key, StringBuffer buf, LoggingEvent event) {
+      Object val = event.getMDC(key);
+      buf.append(' ');
+      if (val != null) {
+        buf.append(val);
+      } else {
+        buf.append('-');
+      }
+    }
+
+    private void opt(String key, StringBuffer buf, LoggingEvent event) {
+      Object val = event.getMDC(key);
+      if (val != null) {
+        buf.append(' ');
+        buf.append(val);
+      }
+    }
+
+    @Override
+    public boolean ignoresThrowable() {
+      return true;
+    }
+
+    @Override
+    public void activateOptions() {
+    }
+  }
+
+  private static final class DieErrorHandler implements ErrorHandler {
+    @Override
+    public void error(String message, Exception e, int errorCode,
+        LoggingEvent event) {
+      error(e != null ? e.getMessage() : message);
+    }
+
+    @Override
+    public void error(String message, Exception e, int errorCode) {
+      error(e != null ? e.getMessage() : message);
+    }
+
+    @Override
+    public void error(String message) {
+      throw new RuntimeException("Cannot open log file: " + message);
+    }
+
+    @Override
+    public void activateOptions() {
+    }
+
+    @Override
+    public void setAppender(Appender appender) {
+    }
+
+    @Override
+    public void setBackupAppender(Appender appender) {
+    }
+
+    @Override
+    public void setLogger(Logger logger) {
+    }
+  }
+
+  private static final class LogLogHandler implements ErrorHandler {
+    @Override
+    public void error(String message, Exception e, int errorCode,
+        LoggingEvent event) {
+      log.error(message, e);
+    }
+
+    @Override
+    public void error(String message, Exception e, int errorCode) {
+      log.error(message, e);
+    }
+
+    @Override
+    public void error(String message) {
+      log.error(message);
+    }
+
+    @Override
+    public void activateOptions() {
+    }
+
+    @Override
+    public void setAppender(Appender appender) {
+    }
+
+    @Override
+    public void setBackupAppender(Appender appender) {
+    }
+
+    @Override
+    public void setLogger(Logger logger) {
+    }
+  }
+}

gerrit-sshd/src/main/java/com/google/gerrit/sshd/SshModule.java

@@ -67,6 +67,7 @@ public class SshModule extends FactoryModule {
     configureCmdLineParser();
 
     install(SshKeyCacheImpl.module());
+    bind(SshLog.class);
     bind(SshInfo.class).to(SshDaemon.class).in(SINGLETON);
     factory(DispatchCommand.Factory.class);
     factory(QueryShell.Factory.class);
@@ -87,6 +88,7 @@ public class SshModule extends FactoryModule {
     install(new LifecycleModule() {
       @Override
       protected void configure() {
+        listener().to(SshLog.class);
         listener().to(SshDaemon.class);
       }
     });

gerrit-sshd/src/main/java/com/google/gerrit/sshd/SshScopes.java

@@ -30,10 +30,15 @@ class SshScopes {
   static class Context {
     final ServerSession session;
     final Map<Key<?>, Object> map;
+    final long created;
+    volatile long started;
+    volatile long finished;
 
     Context(final ServerSession s) {
       session = s;
       map = new HashMap<Key<?>, Object>();
+      created = System.currentTimeMillis();
+      started = created;
     }
   }
 

gerrit-sshd/src/main/java/com/google/gerrit/sshd/SshUtil.java

@@ -49,6 +49,13 @@ public class SshUtil {
   public static final AttributeKey<Integer> SESSION_ID =
       new AttributeKey<Integer>();
 
+  /** Username the last authentication tried to perform as. */
+  static final AttributeKey<String> AUTH_ATTEMPTED_AS =
+      new AttributeKey<String>();
+
+  /** Error message from last authentication attempt. */
+  static final AttributeKey<String> AUTH_ERROR = new AttributeKey<String>();
+
   /**
    * Parse a public key into its Java type.
    *