diff --git a/java/com/google/gerrit/httpd/restapi/RestApiServlet.java b/java/com/google/gerrit/httpd/restapi/RestApiServlet.java index 31d2a8265f..709d485b08 100644 --- a/java/com/google/gerrit/httpd/restapi/RestApiServlet.java +++ b/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; } diff --git a/java/com/google/gerrit/server/git/receive/ReceiveCommits.java b/java/com/google/gerrit/server/git/receive/ReceiveCommits.java index a1f0de54a6..13e55c273a 100644 --- a/java/com/google/gerrit/server/git/receive/ReceiveCommits.java +++ b/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 { diff --git a/java/com/google/gerrit/server/logging/LoggingContext.java b/java/com/google/gerrit/server/logging/LoggingContext.java index 04a23e9c65..2ce4c93b07 100644 --- a/java/com/google/gerrit/server/logging/LoggingContext.java +++ b/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 tags = new ThreadLocal<>(); + private static final ThreadLocal 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; + } } diff --git a/java/com/google/gerrit/server/logging/LoggingContextAwareThreadFactory.java b/java/com/google/gerrit/server/logging/LoggingContextAwareThreadFactory.java index 16d24ac480..05ff0d38f0 100644 --- a/java/com/google/gerrit/server/logging/LoggingContextAwareThreadFactory.java +++ b/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 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); } }); } diff --git a/java/com/google/gerrit/server/logging/TraceContext.java b/java/com/google/gerrit/server/logging/TraceContext.java index cb479cc97d..f85987668d 100644 --- a/java/com/google/gerrit/server/logging/TraceContext.java +++ b/java/com/google/gerrit/server/logging/TraceContext.java @@ -30,6 +30,8 @@ public class TraceContext implements AutoCloseable { // Table private final Table 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 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); + } } } diff --git a/java/com/google/gerrit/sshd/SshCommand.java b/java/com/google/gerrit/sshd/SshCommand.java index 300a602fd1..df0e74805d 100644 --- a/java/com/google/gerrit/sshd/SshCommand.java +++ b/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; } diff --git a/javatests/com/google/gerrit/acceptance/rest/TraceIT.java b/javatests/com/google/gerrit/acceptance/rest/TraceIT.java index 2c32737e20..1369eb3ef1 100644 --- a/javatests/com/google/gerrit/acceptance/rest/TraceIT.java +++ b/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 onCommitReceived(CommitReceivedEvent receiveEvent) throws CommitValidationException { this.foundTraceId = LoggingContext.getInstance().getTagsAsMap().containsKey("TRACE_ID"); + this.isLoggingForced = LoggingContext.getInstance().shouldForceLogging(null, null, false); return ImmutableList.of(); } } diff --git a/javatests/com/google/gerrit/acceptance/ssh/SshTraceIT.java b/javatests/com/google/gerrit/acceptance/ssh/SshTraceIT.java index 9c56d7e5c9..b98ea8c7e9 100644 --- a/javatests/com/google/gerrit/acceptance/ssh/SshTraceIT.java +++ b/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); } } } diff --git a/javatests/com/google/gerrit/server/logging/LoggingContextAwareThreadFactoryTest.java b/javatests/com/google/gerrit/server/logging/LoggingContextAwareThreadFactoryTest.java index bd04d8ae4c..1164e27470 100644 --- a/javatests/com/google/gerrit/server/logging/LoggingContextAwareThreadFactoryTest.java +++ b/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> 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> 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> 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> 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); } } diff --git a/javatests/com/google/gerrit/server/logging/TraceContextTest.java b/javatests/com/google/gerrit/server/logging/TraceContextTest.java index c4ebd29d8d..08e05d3dd1 100644 --- a/javatests/com/google/gerrit/server/logging/TraceContextTest.java +++ b/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> expectedTagMap) { SortedMap> 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); + } }