Force log when trace is enabled

Enable force logging for all log statements when a trace for a REST call
or a Git push is requested.

Force logging means that all log statements will be written
to the error log regardless of the severity of the log statement and the
configured log levels.

This allows to get more information about single requests and makes
debugging them easier.

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

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

@@ -1324,7 +1324,7 @@ public class RestApiServlet extends HttpServlet {
     if (v != null && (v.isEmpty() || Boolean.parseBoolean(v))) {
       RequestId traceId = new RequestId();
       res.setHeader(X_GERRIT_TRACE, traceId.toString());
-      return TraceContext.open().addTag(RequestId.Type.TRACE_ID, traceId);
+      return TraceContext.open().forceLogging().addTag(RequestId.Type.TRACE_ID, traceId);
     }
     return TraceContext.DISABLED;
   }

java/com/google/gerrit/server/git/receive/ReceiveCommits.java

@@ -572,7 +572,7 @@ class ReceiveCommits {
             .addTag(RequestId.Type.RECEIVE_ID, RequestId.forProject(project.getNameKey()))) {
       if (tracePushOption.orElse(false)) {
         RequestId traceId = new RequestId();
-        traceContext.addTag(RequestId.Type.TRACE_ID, traceId);
+        traceContext.forceLogging().addTag(RequestId.Type.TRACE_ID, traceId);
         addMessage(RequestId.Type.TRACE_ID.name() + ": " + traceId);
       }
       try {

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

@@ -33,6 +33,7 @@ public class LoggingContext extends com.google.common.flogger.backend.system.Log
   private static final LoggingContext INSTANCE = new LoggingContext();
 
   private static final ThreadLocal<MutableTags> tags = new ThreadLocal<>();
+  private static final ThreadLocal<Boolean> forceLogging = new ThreadLocal<>();
 
   private LoggingContext() {}
 
@@ -43,7 +44,7 @@ public class LoggingContext extends com.google.common.flogger.backend.system.Log
 
   @Override
   public boolean shouldForceLogging(String loggerName, Level level, boolean isEnabled) {
-    return false;
+    return isLoggingForced();
   }
 
   @Override
@@ -89,4 +90,19 @@ public class LoggingContext extends com.google.common.flogger.backend.system.Log
     }
     return mutableTags;
   }
+
+  boolean isLoggingForced() {
+    Boolean force = forceLogging.get();
+    return force != null ? force : false;
+  }
+
+  boolean forceLogging(boolean force) {
+    Boolean oldValue = forceLogging.get();
+    if (force) {
+      forceLogging.set(true);
+    } else {
+      forceLogging.remove();
+    }
+    return oldValue != null ? oldValue : false;
+  }
 }

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

@@ -37,6 +37,7 @@ public class LoggingContextAwareThreadFactory implements ThreadFactory {
   public Thread newThread(Runnable r) {
     Thread callingThread = Thread.currentThread();
     ImmutableSetMultimap<String, String> tags = LoggingContext.getInstance().getTagsAsMap();
+    boolean forceLogging = LoggingContext.getInstance().isLoggingForced();
     return parentThreadFactory.newThread(
         () -> {
           if (callingThread.equals(Thread.currentThread())) {
@@ -46,11 +47,14 @@ public class LoggingContextAwareThreadFactory implements ThreadFactory {
           }
 
           // propagate logging context
-          LoggingContext.getInstance().setTags(tags);
+          LoggingContext loggingCtx = LoggingContext.getInstance();
+          loggingCtx.setTags(tags);
+          loggingCtx.forceLogging(forceLogging);
           try {
             r.run();
           } finally {
-            LoggingContext.getInstance().clearTags();
+            loggingCtx.clearTags();
+            loggingCtx.forceLogging(false);
           }
         });
   }

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

@@ -30,6 +30,8 @@ public class TraceContext implements AutoCloseable {
   // Table<TAG_NAME, TAG_VALUE, REMOVE_ON_CLOSE>
   private final Table<String, String, Boolean> tags = HashBasedTable.create();
 
+  private boolean stopForceLoggingOnClose;
+
   private TraceContext() {}
 
   public TraceContext addTag(RequestId.Type requestId, Object tagValue) {
@@ -43,6 +45,15 @@ public class TraceContext implements AutoCloseable {
     return this;
   }
 
+  public TraceContext forceLogging() {
+    if (stopForceLoggingOnClose) {
+      return this;
+    }
+
+    stopForceLoggingOnClose = !LoggingContext.getInstance().forceLogging(true);
+    return this;
+  }
+
   @Override
   public void close() {
     for (Table.Cell<String, String, Boolean> cell : tags.cellSet()) {
@@ -50,5 +61,8 @@ public class TraceContext implements AutoCloseable {
         LoggingContext.getInstance().removeTag(cell.getRowKey(), cell.getColumnKey());
       }
     }
+    if (stopForceLoggingOnClose) {
+      LoggingContext.getInstance().forceLogging(false);
+    }
   }
 }

java/com/google/gerrit/sshd/SshCommand.java

@@ -53,7 +53,7 @@ public abstract class SshCommand extends BaseCommand {
     if (trace) {
       RequestId traceId = new RequestId();
       stderr.println(String.format("%s: %s", RequestId.Type.TRACE_ID, traceId));
-      return TraceContext.open().addTag(RequestId.Type.TRACE_ID, traceId);
+      return TraceContext.open().forceLogging().addTag(RequestId.Type.TRACE_ID, traceId);
     }
     return TraceContext.DISABLED;
   }

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

@@ -69,6 +69,7 @@ public class TraceIT extends AbstractDaemonTest {
     assertThat(response.getStatusCode()).isEqualTo(SC_CREATED);
     assertThat(response.getHeader(RestApiServlet.X_GERRIT_TRACE)).isNull();
     assertThat(projectCreationListener.foundTraceId).isFalse();
+    assertThat(projectCreationListener.isLoggingForced).isFalse();
   }
 
   @Test
@@ -78,6 +79,7 @@ public class TraceIT extends AbstractDaemonTest {
     assertThat(response.getStatusCode()).isEqualTo(SC_CREATED);
     assertThat(response.getHeader(RestApiServlet.X_GERRIT_TRACE)).isNotNull();
     assertThat(projectCreationListener.foundTraceId).isTrue();
+    assertThat(projectCreationListener.isLoggingForced).isTrue();
   }
 
   @Test
@@ -87,6 +89,7 @@ public class TraceIT extends AbstractDaemonTest {
     assertThat(response.getStatusCode()).isEqualTo(SC_CREATED);
     assertThat(response.getHeader(RestApiServlet.X_GERRIT_TRACE)).isNotNull();
     assertThat(projectCreationListener.foundTraceId).isTrue();
+    assertThat(projectCreationListener.isLoggingForced).isTrue();
   }
 
   @Test
@@ -96,6 +99,7 @@ public class TraceIT extends AbstractDaemonTest {
     assertThat(response.getStatusCode()).isEqualTo(SC_CREATED);
     assertThat(response.getHeader(RestApiServlet.X_GERRIT_TRACE)).isNull();
     assertThat(projectCreationListener.foundTraceId).isFalse();
+    assertThat(projectCreationListener.isLoggingForced).isFalse();
   }
 
   @Test
@@ -104,6 +108,7 @@ public class TraceIT extends AbstractDaemonTest {
     PushOneCommit.Result r = push.to("refs/heads/master");
     r.assertOkStatus();
     assertThat(commitValidationListener.foundTraceId).isFalse();
+    assertThat(commitValidationListener.isLoggingForced).isFalse();
   }
 
   @Test
@@ -113,6 +118,7 @@ public class TraceIT extends AbstractDaemonTest {
     PushOneCommit.Result r = push.to("refs/heads/master");
     r.assertOkStatus();
     assertThat(commitValidationListener.foundTraceId).isTrue();
+    assertThat(commitValidationListener.isLoggingForced).isTrue();
   }
 
   @Test
@@ -122,6 +128,7 @@ public class TraceIT extends AbstractDaemonTest {
     PushOneCommit.Result r = push.to("refs/heads/master");
     r.assertOkStatus();
     assertThat(commitValidationListener.foundTraceId).isTrue();
+    assertThat(commitValidationListener.isLoggingForced).isTrue();
   }
 
   @Test
@@ -131,6 +138,7 @@ public class TraceIT extends AbstractDaemonTest {
     PushOneCommit.Result r = push.to("refs/heads/master");
     r.assertOkStatus();
     assertThat(commitValidationListener.foundTraceId).isFalse();
+    assertThat(commitValidationListener.isLoggingForced).isFalse();
   }
 
   @Test
@@ -139,6 +147,7 @@ public class TraceIT extends AbstractDaemonTest {
     PushOneCommit.Result r = push.to("refs/for/master");
     r.assertOkStatus();
     assertThat(commitValidationListener.foundTraceId).isFalse();
+    assertThat(commitValidationListener.isLoggingForced).isFalse();
   }
 
   @Test
@@ -148,6 +157,7 @@ public class TraceIT extends AbstractDaemonTest {
     PushOneCommit.Result r = push.to("refs/for/master");
     r.assertOkStatus();
     assertThat(commitValidationListener.foundTraceId).isTrue();
+    assertThat(commitValidationListener.isLoggingForced).isTrue();
   }
 
   @Test
@@ -157,6 +167,7 @@ public class TraceIT extends AbstractDaemonTest {
     PushOneCommit.Result r = push.to("refs/for/master");
     r.assertOkStatus();
     assertThat(commitValidationListener.foundTraceId).isTrue();
+    assertThat(commitValidationListener.isLoggingForced).isTrue();
   }
 
   @Test
@@ -166,25 +177,30 @@ public class TraceIT extends AbstractDaemonTest {
     PushOneCommit.Result r = push.to("refs/for/master");
     r.assertOkStatus();
     assertThat(commitValidationListener.foundTraceId).isFalse();
+    assertThat(commitValidationListener.isLoggingForced).isFalse();
   }
 
   private static class TraceValidatingProjectCreationValidationListener
       implements ProjectCreationValidationListener {
     Boolean foundTraceId;
+    Boolean isLoggingForced;
 
     @Override
     public void validateNewProject(CreateProjectArgs args) throws ValidationException {
       this.foundTraceId = LoggingContext.getInstance().getTagsAsMap().containsKey("TRACE_ID");
+      this.isLoggingForced = LoggingContext.getInstance().shouldForceLogging(null, null, false);
     }
   }
 
   private static class TraceValidatingCommitValidationListener implements CommitValidationListener {
     Boolean foundTraceId;
+    Boolean isLoggingForced;
 
     @Override
     public List<CommitValidationMessage> onCommitReceived(CommitReceivedEvent receiveEvent)
         throws CommitValidationException {
       this.foundTraceId = LoggingContext.getInstance().getTagsAsMap().containsKey("TRACE_ID");
+      this.isLoggingForced = LoggingContext.getInstance().shouldForceLogging(null, null, false);
       return ImmutableList.of();
     }
   }

javatests/com/google/gerrit/acceptance/ssh/SshTraceIT.java

@@ -40,6 +40,7 @@ public class SshTraceIT extends AbstractDaemonTest {
     adminSshSession.exec("gerrit create-project new1");
     adminSshSession.assertSuccess();
     assertThat(projectCreationListener.foundTraceId).isFalse();
+    assertThat(projectCreationListener.isLoggingForced).isFalse();
   }
 
   @Test
@@ -50,15 +51,18 @@ public class SshTraceIT extends AbstractDaemonTest {
     adminSshSession.assertFailure(RequestId.Type.TRACE_ID.name());
 
     assertThat(projectCreationListener.foundTraceId).isTrue();
+    assertThat(projectCreationListener.isLoggingForced).isTrue();
   }
 
   private static class TraceValidatingProjectCreationValidationListener
       implements ProjectCreationValidationListener {
     Boolean foundTraceId;
+    Boolean isLoggingForced;
 
     @Override
     public void validateNewProject(CreateProjectArgs args) throws ValidationException {
       this.foundTraceId = LoggingContext.getInstance().getTagsAsMap().containsKey("TRACE_ID");
+      this.isLoggingForced = LoggingContext.getInstance().shouldForceLogging(null, null, false);
     }
   }
 }

javatests/com/google/gerrit/server/logging/LoggingContextAwareThreadFactoryTest.java

@@ -28,61 +28,82 @@ public class LoggingContextAwareThreadFactoryTest {
   @Test
   public void loggingContextPropagationToNewThread() throws Exception {
     assertThat(LoggingContext.getInstance().getTags().isEmpty()).isTrue();
-    try (TraceContext traceContext = TraceContext.open().addTag("foo", "bar")) {
+    assertForceLogging(false);
+    try (TraceContext traceContext = TraceContext.open().forceLogging().addTag("foo", "bar")) {
       SortedMap<String, SortedSet<Object>> tagMap = LoggingContext.getInstance().getTags().asMap();
       assertThat(tagMap.keySet()).containsExactly("foo");
       assertThat(tagMap.get("foo")).containsExactly("bar");
+      assertForceLogging(true);
 
       Thread thread =
           new LoggingContextAwareThreadFactory(r -> new Thread(r, "test-thread"))
               .newThread(
                   () -> {
-                    // Verify that the tags have been propagated to the new thread.
+                    // Verify that the tags and force logging flag have been propagated to the new
+                    // thread.
                     SortedMap<String, SortedSet<Object>> threadTagMap =
                         LoggingContext.getInstance().getTags().asMap();
                     expect.that(threadTagMap.keySet()).containsExactly("foo");
                     expect.that(threadTagMap.get("foo")).containsExactly("bar");
+                    expect
+                        .that(LoggingContext.getInstance().shouldForceLogging(null, null, false))
+                        .isTrue();
                   });
 
       // Execute in background.
       thread.start();
       thread.join();
 
-      // Verify that tags in the outer thread are still set.
+      // Verify that tags and force logging flag in the outer thread are still set.
       tagMap = LoggingContext.getInstance().getTags().asMap();
       assertThat(tagMap.keySet()).containsExactly("foo");
       assertThat(tagMap.get("foo")).containsExactly("bar");
+      assertForceLogging(true);
     }
     assertThat(LoggingContext.getInstance().getTags().isEmpty()).isTrue();
+    assertForceLogging(false);
   }
 
   @Test
   public void loggingContextPropagationToSameThread() throws Exception {
     assertThat(LoggingContext.getInstance().getTags().isEmpty()).isTrue();
-    try (TraceContext traceContext = TraceContext.open().addTag("foo", "bar")) {
+    assertForceLogging(false);
+    try (TraceContext traceContext = TraceContext.open().forceLogging().addTag("foo", "bar")) {
       SortedMap<String, SortedSet<Object>> tagMap = LoggingContext.getInstance().getTags().asMap();
       assertThat(tagMap.keySet()).containsExactly("foo");
       assertThat(tagMap.get("foo")).containsExactly("bar");
+      assertForceLogging(true);
 
       Thread thread =
           new LoggingContextAwareThreadFactory()
               .newThread(
                   () -> {
-                    // Verify that the tags have been propagated to the new thread.
+                    // Verify that the tags and force logging flag have been propagated to the new
+                    // thread.
                     SortedMap<String, SortedSet<Object>> threadTagMap =
                         LoggingContext.getInstance().getTags().asMap();
                     expect.that(threadTagMap.keySet()).containsExactly("foo");
                     expect.that(threadTagMap.get("foo")).containsExactly("bar");
+                    expect
+                        .that(LoggingContext.getInstance().shouldForceLogging(null, null, false))
+                        .isTrue();
                   });
 
       // Execute in the same thread.
       thread.run();
 
-      // Verify that tags in the outer thread are still set.
+      // Verify that tags and force logging flag in the outer thread are still set.
       tagMap = LoggingContext.getInstance().getTags().asMap();
       assertThat(tagMap.keySet()).containsExactly("foo");
       assertThat(tagMap.get("foo")).containsExactly("bar");
+      assertForceLogging(true);
     }
     assertThat(LoggingContext.getInstance().getTags().isEmpty()).isTrue();
+    assertForceLogging(false);
+  }
+
+  private void assertForceLogging(boolean expected) {
+    assertThat(LoggingContext.getInstance().shouldForceLogging(null, null, false))
+        .isEqualTo(expected);
   }
 }

javatests/com/google/gerrit/server/logging/TraceContextTest.java

@@ -29,6 +29,7 @@ public class TraceContextTest {
   @After
   public void cleanup() {
     LoggingContext.getInstance().clearTags();
+    LoggingContext.getInstance().forceLogging(false);
   }
 
   @Test
@@ -108,6 +109,52 @@ public class TraceContextTest {
     assertTags(ImmutableMap.of());
   }
 
+  @Test
+  public void openContextWithForceLogging() {
+    assertForceLogging(false);
+    try (TraceContext traceContext = TraceContext.open().forceLogging()) {
+      assertForceLogging(true);
+    }
+    assertForceLogging(false);
+  }
+
+  @Test
+  public void openNestedContextsWithForceLogging() {
+    assertForceLogging(false);
+    try (TraceContext traceContext = TraceContext.open().forceLogging()) {
+      assertForceLogging(true);
+
+      try (TraceContext traceContext2 = TraceContext.open()) {
+        // force logging is still enabled since outer trace context forced logging
+        assertForceLogging(true);
+
+        try (TraceContext traceContext3 = TraceContext.open().forceLogging()) {
+          assertForceLogging(true);
+        }
+
+        assertForceLogging(true);
+      }
+
+      assertForceLogging(true);
+    }
+    assertForceLogging(false);
+  }
+
+  @Test
+  public void forceLogging() {
+    assertForceLogging(false);
+    try (TraceContext traceContext = TraceContext.open()) {
+      assertForceLogging(false);
+
+      traceContext.forceLogging();
+      assertForceLogging(true);
+
+      traceContext.forceLogging();
+      assertForceLogging(true);
+    }
+    assertForceLogging(false);
+  }
+
   private void assertTags(ImmutableMap<String, ImmutableSet<String>> expectedTagMap) {
     SortedMap<String, SortedSet<Object>> actualTagMap =
         LoggingContext.getInstance().getTags().asMap();
@@ -117,4 +164,9 @@ public class TraceContextTest {
           .containsExactlyElementsIn(expectedEntry.getValue());
     }
   }
+
+  private void assertForceLogging(boolean expected) {
+    assertThat(LoggingContext.getInstance().shouldForceLogging(null, null, false))
+        .isEqualTo(expected);
+  }
 }