Support tracing for single REST requests

To investigate why a certain REST call failed one needs to find matching
messages in the logs. Sometimes this is not as easy as it sounds:

1) Error reports may not tell exactly which REST endpoint was invoked
   and what were the IDs of the REST resources on which it was invoked.
2) For busy servers finding logs that correspond to the failing REST
   call may be difficult because of the huge amount of logs. Matching
   logs by the timestamp of when the request was done may also not be
   straight-forward if the user is in a different timezone than the
   server.
3) The error log normally only contains errors, but no detailed debug
   information.
4) Enabling debug logs effects all requests and usually results in a lot
   of log spam.

The idea is to enable debug traces on need for single requests:

a) A debug trace is enabled by setting the 'trace' request parameter
b) The response contains an 'X-Gerrit-Trace' header with the trace ID
c) An administrator can use the trace ID to find all logs for this
   request in the error log.
d) The debug trace can contain additional debug information which is not
   written when tracing is disabled.

This change implements a), b) and c) for REST requests. If the trace
parameter is set for a REST request we open a trace context that sets a
logging tag with a generated trace ID that is then automatically
included into all log statements that are triggered by this request. The
trace ID is returned to the client as 'X-Gerrit-Trace' header in the
response.

d) will be implemented by a follow-up change which will make use of
Flogger's force log functionality.

Change-Id: Ic79aadedbe5d73e94daefa6aa9d207edbffc1607
Signed-off-by: Edwin Kempin <ekempin@google.com>

java/com/google/gerrit/httpd/restapi/ParameterParser.java

@@ -56,8 +56,10 @@ import javax.servlet.http.HttpServletResponse;
 import org.kohsuke.args4j.CmdLineException;
 
 public class ParameterParser {
+  public static final String TRACE_PARAMETER = "trace";
+
   private static final ImmutableSet<String> RESERVED_KEYS =
-      ImmutableSet.of("pp", "prettyPrint", "strict", "callback", "alt", "fields");
+      ImmutableSet.of("pp", "prettyPrint", "strict", "callback", "alt", "fields", TRACE_PARAMETER);
 
   @AutoValue
   public abstract static class QueryParams {

java/com/google/gerrit/httpd/restapi/RestApiServlet.java

@@ -48,6 +48,7 @@ import static javax.servlet.http.HttpServletResponse.SC_OK;
 import static javax.servlet.http.HttpServletResponse.SC_PRECONDITION_FAILED;
 import static javax.servlet.http.HttpServletResponse.SC_SERVICE_UNAVAILABLE;
 
+import com.google.common.annotations.VisibleForTesting;
 import com.google.common.base.CharMatcher;
 import com.google.common.base.Joiner;
 import com.google.common.base.Splitter;
@@ -107,10 +108,12 @@ import com.google.gerrit.server.audit.ExtendedHttpAuditEvent;
 import com.google.gerrit.server.cache.PerThreadCache;
 import com.google.gerrit.server.config.GerritServerConfig;
 import com.google.gerrit.server.git.LockFailureException;
+import com.google.gerrit.server.logging.TraceContext;
 import com.google.gerrit.server.permissions.GlobalPermission;
 import com.google.gerrit.server.permissions.PermissionBackend;
 import com.google.gerrit.server.permissions.PermissionBackendException;
 import com.google.gerrit.server.update.UpdateException;
+import com.google.gerrit.server.util.RequestId;
 import com.google.gerrit.util.http.CacheHeaders;
 import com.google.gerrit.util.http.RequestUtil;
 import com.google.gson.ExclusionStrategy;
@@ -177,6 +180,8 @@ public class RestApiServlet extends HttpServlet {
 
   private static final String FORM_TYPE = "application/x-www-form-urlencoded";
 
+  @VisibleForTesting public static final String X_GERRIT_TRACE = "X-Gerrit-Trace";
+
   // HTTP 422 Unprocessable Entity.
   // TODO: Remove when HttpServletResponse.SC_UNPROCESSABLE_ENTITY is available
   private static final int SC_UNPROCESSABLE_ENTITY = 422;
@@ -280,7 +285,9 @@ public class RestApiServlet extends HttpServlet {
     RestResource rsrc = TopLevelResource.INSTANCE;
     ViewData viewData = null;
 
+    try (TraceContext traceContext = enableTracing(req, res)) {
       try (PerThreadCache ignored = PerThreadCache.create()) {
+
         if (isCorsPreflight(req)) {
           doCorsPreflight(req, res);
           return;
@@ -524,7 +531,8 @@ public class RestApiServlet extends HttpServlet {
         }
       } catch (MalformedJsonException | JsonParseException e) {
         responseBytes =
-          replyError(req, res, status = SC_BAD_REQUEST, "Invalid " + JSON_TYPE + " in request", e);
+            replyError(
+                req, res, status = SC_BAD_REQUEST, "Invalid " + JSON_TYPE + " in request", e);
       } catch (BadRequestException e) {
         responseBytes =
             replyError(
@@ -574,7 +582,8 @@ public class RestApiServlet extends HttpServlet {
         Throwable t = e.getCause();
         if (t instanceof LockFailureException) {
           responseBytes =
-            replyError(req, res, status = SC_SERVICE_UNAVAILABLE, messageOr(t, "Lock failure"), e);
+              replyError(
+                  req, res, status = SC_SERVICE_UNAVAILABLE, messageOr(t, "Lock failure"), e);
         } else {
           status = SC_INTERNAL_SERVER_ERROR;
           responseBytes = handleException(e, req, res);
@@ -608,6 +617,7 @@ public class RestApiServlet extends HttpServlet {
                 viewData == null ? null : viewData.view));
       }
     }
+  }
 
   private static HttpServletRequest applyXdOverrides(HttpServletRequest req, QueryParams qp)
       throws BadRequestException {
@@ -1265,6 +1275,16 @@ public class RestApiServlet extends HttpServlet {
     }
   }
 
+  private TraceContext enableTracing(HttpServletRequest req, HttpServletResponse res) {
+    String v = req.getParameter(ParameterParser.TRACE_PARAMETER);
+    if (v != null && (v.isEmpty() || Boolean.parseBoolean(v))) {
+      RequestId traceId = new RequestId();
+      res.setHeader(X_GERRIT_TRACE, traceId.toString());
+      return new TraceContext(RequestId.Type.TRACE_ID, traceId);
+    }
+    return TraceContext.DISABLED;
+  }
+
   private boolean isDelete(HttpServletRequest req) {
     return "DELETE".equals(req.getMethod());
   }

java/com/google/gerrit/server/logging/TraceContext.java

@@ -19,6 +19,8 @@ import static com.google.common.base.Preconditions.checkNotNull;
 import com.google.gerrit.server.util.RequestId;
 
 public class TraceContext implements AutoCloseable {
+  public static final TraceContext DISABLED = new TraceContext();
+
   private final String tagName;
   private final String tagValue;
   private final boolean removeOnClose;
@@ -33,6 +35,12 @@ public class TraceContext implements AutoCloseable {
     this.removeOnClose = LoggingContext.getInstance().addTag(this.tagName, this.tagValue);
   }
 
+  private TraceContext() {
+    this.tagName = null;
+    this.tagValue = null;
+    this.removeOnClose = false;
+  }
+
   @Override
   public void close() {
     if (removeOnClose) {

java/com/google/gerrit/server/util/RequestId.java

@@ -17,6 +17,7 @@ package com.google.gerrit.server.util;
 import com.google.common.base.Enums;
 import com.google.common.hash.Hasher;
 import com.google.common.hash.Hashing;
+import com.google.gerrit.common.Nullable;
 import com.google.gerrit.common.TimeUtil;
 import com.google.gerrit.reviewdb.client.Change;
 import com.google.gerrit.reviewdb.client.Project;
@@ -40,7 +41,8 @@ public class RequestId {
 
   public enum Type {
     RECEIVE_ID,
-    SUBMISSION_ID;
+    SUBMISSION_ID,
+    TRACE_ID;
 
     static boolean isId(String id) {
       return id != null && Enums.getIfPresent(Type.class, id).isPresent();
@@ -61,10 +63,18 @@ public class RequestId {
 
   private final String str;
 
-  private RequestId(String resourceId) {
+  public RequestId() {
+    this(null);
+  }
+
+  private RequestId(@Nullable String resourceId) {
     Hasher h = Hashing.murmur3_128().newHasher();
     h.putLong(Thread.currentThread().getId()).putUnencodedChars(MACHINE_ID);
-    str = resourceId + "-" + TimeUtil.nowTs().getTime() + "-" + h.hash().toString().substring(0, 8);
+    str =
+        (resourceId != null ? resourceId + "-" : "")
+            + TimeUtil.nowTs().getTime()
+            + "-"
+            + h.hash().toString().substring(0, 8);
   }
 
   @Override

javatests/com/google/gerrit/acceptance/rest/TraceIT.java

@@ -0,0 +1,96 @@
+// Copyright (C) 2018 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.acceptance.rest;
+
+import static com.google.common.truth.Truth.assertThat;
+import static org.apache.http.HttpStatus.SC_CREATED;
+
+import com.google.gerrit.acceptance.AbstractDaemonTest;
+import com.google.gerrit.acceptance.RestResponse;
+import com.google.gerrit.extensions.registration.DynamicSet;
+import com.google.gerrit.extensions.registration.RegistrationHandle;
+import com.google.gerrit.httpd.restapi.ParameterParser;
+import com.google.gerrit.httpd.restapi.RestApiServlet;
+import com.google.gerrit.server.logging.LoggingContext;
+import com.google.gerrit.server.project.CreateProjectArgs;
+import com.google.gerrit.server.validators.ProjectCreationValidationListener;
+import com.google.gerrit.server.validators.ValidationException;
+import com.google.inject.Inject;
+import org.junit.After;
+import org.junit.Before;
+import org.junit.Test;
+
+public class TraceIT extends AbstractDaemonTest {
+  @Inject private DynamicSet<ProjectCreationValidationListener> projectCreationValidationListeners;
+
+  private TraceValidatingProjectCreationValidationListener listener;
+  private RegistrationHandle registrationHandle;
+
+  @Before
+  public void setup() {
+    listener = new TraceValidatingProjectCreationValidationListener();
+    registrationHandle = projectCreationValidationListeners.add(listener);
+  }
+
+  @After
+  public void cleanup() {
+    registrationHandle.remove();
+  }
+
+  @Test
+  public void withoutTrace() throws Exception {
+    RestResponse response = adminRestSession.put("/projects/new1");
+    assertThat(response.getStatusCode()).isEqualTo(SC_CREATED);
+    assertThat(response.getHeader(RestApiServlet.X_GERRIT_TRACE)).isNull();
+    assertThat(listener.foundTraceId).isFalse();
+  }
+
+  @Test
+  public void withTrace() throws Exception {
+    RestResponse response =
+        adminRestSession.put("/projects/new2?" + ParameterParser.TRACE_PARAMETER);
+    assertThat(response.getStatusCode()).isEqualTo(SC_CREATED);
+    assertThat(response.getHeader(RestApiServlet.X_GERRIT_TRACE)).isNotNull();
+    assertThat(listener.foundTraceId).isTrue();
+  }
+
+  @Test
+  public void withTraceTrue() throws Exception {
+    RestResponse response =
+        adminRestSession.put("/projects/new3?" + ParameterParser.TRACE_PARAMETER + "=true");
+    assertThat(response.getStatusCode()).isEqualTo(SC_CREATED);
+    assertThat(response.getHeader(RestApiServlet.X_GERRIT_TRACE)).isNotNull();
+    assertThat(listener.foundTraceId).isTrue();
+  }
+
+  @Test
+  public void withTraceFalse() throws Exception {
+    RestResponse response =
+        adminRestSession.put("/projects/new4?" + ParameterParser.TRACE_PARAMETER + "=false");
+    assertThat(response.getStatusCode()).isEqualTo(SC_CREATED);
+    assertThat(response.getHeader(RestApiServlet.X_GERRIT_TRACE)).isNull();
+    assertThat(listener.foundTraceId).isFalse();
+  }
+
+  private static class TraceValidatingProjectCreationValidationListener
+      implements ProjectCreationValidationListener {
+    Boolean foundTraceId;
+
+    @Override
+    public void validateNewProject(CreateProjectArgs args) throws ValidationException {
+      this.foundTraceId = LoggingContext.getInstance().getTagsAsMap().containsKey("TRACE_ID");
+    }
+  }
+}