Log HTTP activity to $site_path/logs/httpd_log

If we aren't in proxy server mode we now log HTTP request to an
NCSA combined log format file.  Unfortunately I wrote our own log
file implementation because the stock Jetty NCSARequestLog class
uses a different file rotation system than we prefer.

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

Documentation/config-gerrit.txt

@@ -841,6 +841,15 @@ password during startup.
 +
 By default, `gerrit`.
 
+[[httpd.requestLog]]httpd.requestLog::
++
+Enable (or disable) the `'$site_path'/logs/httpd_log` request log.
+If enabled, an NCSA combined log format request log file is written
+out by the internal HTTP daemon.
++
+By default, true if httpd.listenUrl uses http:// or https://,
+and false if httpd.listenUrl uses proxy-http:// or proxy-https://.
+
 [[httpd.acceptorThreads]]httpd.acceptorThreads::
 +
 Number of worker threads dedicated to accepting new incoming TCP

gerrit-pgm/src/main/java/com/google/gerrit/pgm/Daemon.java

@@ -200,6 +200,6 @@ public class Daemon extends SiteProgram {
   private Injector createHttpdInjector() {
     final List<Module> modules = new ArrayList<Module>();
     modules.add(new JettyModule(new JettyEnv(webInjector)));
-    return sysInjector.createChildInjector(modules);
+    return webInjector.createChildInjector(modules);
   }
 }

gerrit-pgm/src/main/java/com/google/gerrit/pgm/http/jetty/HttpLog.java

@@ -0,0 +1,330 @@
+// Copyright (C) 2010 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.pgm.http.jetty;
+
+import com.google.gerrit.server.CurrentUser;
+import com.google.gerrit.server.IdentifiedUser;
+import com.google.gerrit.server.config.SitePaths;
+import com.google.inject.Provider;
+import com.google.inject.servlet.GuiceHelper;
+
+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.eclipse.jetty.server.Request;
+import org.eclipse.jetty.server.RequestLog;
+import org.eclipse.jetty.server.Response;
+import org.eclipse.jetty.util.component.AbstractLifeCycle;
+
+import java.io.File;
+import java.io.IOException;
+import java.text.SimpleDateFormat;
+import java.util.Date;
+import java.util.TimeZone;
+
+/** Writes the {@code httpd_log} file with per-request data. */
+class HttpLog extends AbstractLifeCycle implements RequestLog {
+  private static final Logger log = Logger.getLogger(HttpLog.class);
+  private static final String LOG_NAME = "httpd_log";
+
+  private static final String P_HOST = "Host";
+  private static final String P_USER = "User";
+  private static final String P_METHOD = "Method";
+  private static final String P_RESOURCE = "Resource";
+  private static final String P_PROTOCOL = "Version";
+  private static final String P_STATUS = "Status";
+  private static final String P_CONTENT_LENGTH = "Content-Length";
+  private static final String P_REFERER = "Referer";
+  private static final String P_USER_AGENT = "User-Agent";
+
+  private final AsyncAppender async;
+  private final Provider<CurrentUser> userProvider;
+
+  HttpLog(final SitePaths site, final Provider<CurrentUser> userProvider) {
+    this.userProvider = userProvider;
+
+    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
+  protected void doStart() throws Exception {
+  }
+
+  @Override
+  protected void doStop() throws Exception {
+    async.close();
+  }
+
+  @Override
+  public void log(final Request req, final Response rsp) {
+    GuiceHelper.runInContext(req, rsp, new Runnable() {
+      @Override
+      public void run() {
+        doLog(req, rsp);
+      }
+    });
+  }
+
+  private void doLog(Request req, Response rsp) {
+    final LoggingEvent event = new LoggingEvent( //
+        Logger.class.getName(), // fqnOfCategoryClass
+        null, // logger (optional)
+        System.currentTimeMillis(), // when
+        Level.INFO, // level
+        "", // message text
+        "HTTPD", // thread name
+        null, // exception information
+        null, // current NDC string
+        null, // caller location
+        null // MDC properties
+        );
+
+    String uri = req.getRequestURI();
+    String qs = req.getQueryString();
+    if (qs != null) {
+      uri = uri + "?" + qs;
+    }
+
+    CurrentUser user = userProvider.get();
+    if (user instanceof IdentifiedUser) {
+      IdentifiedUser who = (IdentifiedUser) user;
+      if (who.getUserName() != null && !who.getUserName().isEmpty()) {
+        event.setProperty(P_USER, who.getUserName());
+      } else {
+        event.setProperty(P_USER, "a/" + who.getAccountId());
+      }
+    }
+
+    set(event, P_HOST, req.getRemoteAddr());
+    set(event, P_METHOD, req.getMethod());
+    set(event, P_RESOURCE, uri);
+    set(event, P_PROTOCOL, req.getProtocol());
+    set(event, P_STATUS, rsp.getStatus());
+    set(event, P_CONTENT_LENGTH, rsp.getContentCount());
+    set(event, P_REFERER, req.getHeader("Referer"));
+    set(event, P_USER_AGENT, req.getHeader("User-Agent"));
+
+    async.append(event);
+  }
+
+  private static void set(LoggingEvent event, String key, String val) {
+    if (val != null && !val.isEmpty()) {
+      event.setProperty(key, val);
+    }
+  }
+
+  private static void set(LoggingEvent event, String key, long val) {
+    if (0 < val) {
+      event.setProperty(key, String.valueOf(val));
+    }
+  }
+
+  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 SimpleDateFormat dateFormat;
+    private long lastTimeMillis;
+    private String lastTimeString;
+
+    MyLayout() {
+      final TimeZone tz = TimeZone.getDefault();
+      dateFormat = new SimpleDateFormat("dd/MMM/yyyy:HH:mm:ss Z");
+      dateFormat.setTimeZone(tz);
+
+      lastTimeMillis = System.currentTimeMillis();
+      lastTimeString = dateFormat.format(new Date(lastTimeMillis));
+    }
+
+    @Override
+    public String format(LoggingEvent event) {
+      final StringBuilder buf = new StringBuilder(128);
+
+      opt(buf, event, P_HOST);
+
+      buf.append(' ');
+      buf.append('-'); // identd on client system (never requested)
+
+      buf.append(' ');
+      opt(buf, event, P_USER);
+
+      buf.append(' ');
+      buf.append('[');
+      formatDate(event.getTimeStamp(), buf);
+      buf.append(']');
+
+      buf.append(' ');
+      buf.append('"');
+      buf.append(event.getMDC(P_METHOD));
+      buf.append(' ');
+      buf.append(event.getMDC(P_RESOURCE));
+      buf.append(' ');
+      buf.append(event.getMDC(P_PROTOCOL));
+      buf.append('"');
+
+      buf.append(' ');
+      buf.append(event.getMDC(P_STATUS));
+
+      buf.append(' ');
+      opt(buf, event, P_CONTENT_LENGTH);
+
+      buf.append(' ');
+      dq_opt(buf, event, P_REFERER);
+
+      buf.append(' ');
+      dq_opt(buf, event, P_USER_AGENT);
+
+      buf.append('\n');
+      return buf.toString();
+    }
+
+    private void opt(StringBuilder buf, LoggingEvent event, String key) {
+      String val = (String) event.getMDC(key);
+      if (val == null) {
+        buf.append('-');
+      } else {
+        buf.append(val);
+      }
+    }
+
+    private void dq_opt(StringBuilder buf, LoggingEvent event, String key) {
+      String val = (String) event.getMDC(key);
+      if (val == null) {
+        buf.append('-');
+      } else {
+        buf.append('"');
+        buf.append(val);
+        buf.append('"');
+      }
+    }
+
+    private void formatDate(final long now, final StringBuilder sbuf) {
+      final long rounded = now - (int) (now % 1000);
+      if (rounded != lastTimeMillis) {
+        synchronized (dateFormat) {
+          lastTimeMillis = rounded;
+          lastTimeString = dateFormat.format(new Date(lastTimeMillis));
+          sbuf.append(lastTimeString);
+        }
+      } else {
+        sbuf.append(lastTimeString);
+      }
+    }
+
+    @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-pgm/src/main/java/com/google/gerrit/pgm/http/jetty/JettyServer.java

@@ -19,10 +19,12 @@ import static java.util.concurrent.TimeUnit.SECONDS;
 
 import com.google.gerrit.launcher.GerritLauncher;
 import com.google.gerrit.lifecycle.LifecycleListener;
+import com.google.gerrit.server.CurrentUser;
 import com.google.gerrit.server.config.GerritServerConfig;
 import com.google.gerrit.server.config.SitePaths;
 import com.google.inject.Inject;
 import com.google.inject.Injector;
+import com.google.inject.Provider;
 import com.google.inject.Singleton;
 import com.google.inject.servlet.GuiceFilter;
 import com.google.inject.servlet.GuiceServletContextListener;
@@ -34,6 +36,7 @@ import org.eclipse.jetty.server.Request;
 import org.eclipse.jetty.server.Server;
 import org.eclipse.jetty.server.handler.ContextHandler;
 import org.eclipse.jetty.server.handler.ContextHandlerCollection;
+import org.eclipse.jetty.server.handler.RequestLogHandler;
 import org.eclipse.jetty.server.nio.SelectChannelConnector;
 import org.eclipse.jetty.server.ssl.SslSelectChannelConnector;
 import org.eclipse.jetty.servlet.DefaultServlet;
@@ -95,19 +98,28 @@ public class JettyServer {
   private final SitePaths site;
   private final Server httpd;
 
+  private boolean reverseProxy;
+
   /** Location on disk where our WAR file was unpacked to. */
   private Resource baseResource;
 
   @Inject
   JettyServer(@GerritServerConfig final Config cfg, final SitePaths site,
-      final JettyEnv env) throws MalformedURLException, IOException {
+      final JettyEnv env, final Provider<CurrentUser> userProvider)
+      throws MalformedURLException, IOException {
     this.site = site;
 
-    Handler app = makeContext(env, cfg);
-
     httpd = new Server();
     httpd.setConnectors(listen(cfg));
     httpd.setThreadPool(threadPool(cfg));
+
+    Handler app = makeContext(env, cfg);
+    if (cfg.getBoolean("httpd", "requestlog", !reverseProxy)) {
+      RequestLogHandler handler = new RequestLogHandler();
+      handler.setRequestLog(new HttpLog(site, userProvider));
+      handler.setHandler(app);
+      app = handler;
+    }
     httpd.setHandler(app);
 
     httpd.setStopAtShutdown(false);
@@ -128,6 +140,7 @@ public class JettyServer {
     final boolean reuseAddress = cfg.getBoolean("httpd", "reuseaddress", true);
     final int acceptors = cfg.getInt("httpd", "acceptorThreads", 2);
 
+    reverseProxy = true;
     final Connector[] connectors = new Connector[listenUrls.length];
     for (int idx = 0; idx < listenUrls.length; idx++) {
       final URI u = listenUrls[idx];
@@ -135,6 +148,7 @@ public class JettyServer {
       final SelectChannelConnector c;
 
       if ("http".equals(u.getScheme())) {
+        reverseProxy = false;
         defaultPort = 80;
         c = new SelectChannelConnector();
 
@@ -150,6 +164,7 @@ public class JettyServer {
         ssl.setKeyPassword(password);
         ssl.setTrustPassword(password);
 
+        reverseProxy = false;
         defaultPort = 443;
         c = ssl;
 

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

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

gerrit-pgm/src/main/java/com/google/inject/servlet/GuiceHelper.java

@@ -0,0 +1,36 @@
+// Copyright (C) 2010 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.inject.servlet;
+
+import com.google.inject.servlet.GuiceFilter.Context;
+
+import javax.servlet.http.HttpServletRequest;
+import javax.servlet.http.HttpServletResponse;
+
+public class GuiceHelper {
+  public static void runInContext(HttpServletRequest req,
+      HttpServletResponse rsp, Runnable thunk) {
+    Context previous = GuiceFilter.localContext.get();
+    try {
+      GuiceFilter.localContext.set(new Context(req, rsp));
+      thunk.run();
+    } finally {
+      GuiceFilter.localContext.set(previous);
+    }
+  }
+
+  private GuiceHelper() {
+  }
+}