From 63964e4fbae8acf7fd6910c8bddf2f98d8ac7424 Mon Sep 17 00:00:00 2001 From: Stuart Douglas Date: Fri, 22 Jan 2021 15:27:20 +1100 Subject: [PATCH] Add hang detection to @QuarkusTest This will dump a stack trace if the test appears to have hung. --- .../deployment/configuration/TestConfig.java | 21 ++++ .../asciidoc/getting-started-testing.adoc | 11 ++ .../src/main/resources/application.properties | 2 +- .../test/junit/QuarkusTestExtension.java | 101 ++++++++++++++++-- 4 files changed, 127 insertions(+), 8 deletions(-) create mode 100644 core/deployment/src/main/java/io/quarkus/deployment/configuration/TestConfig.java diff --git a/core/deployment/src/main/java/io/quarkus/deployment/configuration/TestConfig.java b/core/deployment/src/main/java/io/quarkus/deployment/configuration/TestConfig.java new file mode 100644 index 0000000000000..de0fee867fb46 --- /dev/null +++ b/core/deployment/src/main/java/io/quarkus/deployment/configuration/TestConfig.java @@ -0,0 +1,21 @@ +package io.quarkus.deployment.configuration; + +import java.time.Duration; + +import io.quarkus.runtime.annotations.ConfigItem; +import io.quarkus.runtime.annotations.ConfigRoot; + +@ConfigRoot +public class TestConfig { + + /** + * Configures the hang detection in @QuarkusTest. If no activity happens (i.e. no test callbacks are called) over + * this period then QuarkusTest will dump all threads stack traces, to help diagnose a potential hang. + * + * Note that the initial timeout (before Quarkus has started) will only apply if provided by a system property, as + * it is not possible to read all config sources until Quarkus has booted. + */ + @ConfigItem(defaultValue = "10m") + Duration hangDetectionTimeout; + +} diff --git a/docs/src/main/asciidoc/getting-started-testing.adoc b/docs/src/main/asciidoc/getting-started-testing.adoc index e7807e233825d..bf58a089b5114 100644 --- a/docs/src/main/asciidoc/getting-started-testing.adoc +++ b/docs/src/main/asciidoc/getting-started-testing.adoc @@ -895,6 +895,17 @@ but it is common to create custom implementations to address specific applicatio Common cases include starting docker containers using https://www.testcontainers.org/[Testcontainers] (an example of which can be found https://github.com/quarkusio/quarkus-quickstarts/blob/master/kafka-quickstart/src/test/java/org/acme/kafka/KafkaResource.java[here]), or starting a mock HTTP server using http://wiremock.org/[Wiremock] (an example of which can be found https://github.com/geoand/quarkus-test-demo/blob/master/src/test/java/org/acme/getting/started/country/WiremockCountries.java[here]). +== Hang Detection + +`@QuarkusTest` has support for hang detection to help diagnose any unexpected hangs. If no progress is made for a specified +time (i.e. no JUnit callbacks are invoked) then Quarkus will print a stack trace to the console to help diagnose the hang. +The default value for this timeout is 10 minutes. + +No further action will be taken, and the tests will continue as normal (generally until CI times out), however the printed +stack traces should help diagnose why the build has failed. You can control this timeout with the +`quarkus.test.hang-detection-timeout` system property (you can also set this in application.properties, but this won't +be read until Quarkus has started, so the timeout for Quarkus start will be the default of 10 minutes). + == Native Executable Testing It is also possible to test native executables using `@NativeImageTest`. This supports all the features mentioned in this diff --git a/integration-tests/main/src/main/resources/application.properties b/integration-tests/main/src/main/resources/application.properties index fcfeb9bb71594..7ccecc6bfb907 100644 --- a/integration-tests/main/src/main/resources/application.properties +++ b/integration-tests/main/src/main/resources/application.properties @@ -45,4 +45,4 @@ quarkus.native.resources.excludes = **/unwanted.* quarkus.log.metrics.enabled=true -quarkus.native.additional-build-args =-H:ReflectionConfigurationFiles=reflection-config.json \ No newline at end of file +quarkus.native.additional-build-args =-H:ReflectionConfigurationFiles=reflection-config.json diff --git a/test-framework/junit5/src/main/java/io/quarkus/test/junit/QuarkusTestExtension.java b/test-framework/junit5/src/main/java/io/quarkus/test/junit/QuarkusTestExtension.java index 4cc3e533c7c5c..5168c87531e6b 100644 --- a/test-framework/junit5/src/main/java/io/quarkus/test/junit/QuarkusTestExtension.java +++ b/test-framework/junit5/src/main/java/io/quarkus/test/junit/QuarkusTestExtension.java @@ -6,12 +6,16 @@ import java.io.Closeable; import java.io.File; import java.io.IOException; +import java.lang.management.ManagementFactory; +import java.lang.management.ThreadInfo; import java.lang.reflect.Constructor; import java.lang.reflect.InvocationTargetException; import java.lang.reflect.Method; import java.nio.file.Files; import java.nio.file.Path; import java.nio.file.Paths; +import java.time.Duration; +import java.time.temporal.ChronoUnit; import java.util.AbstractMap; import java.util.ArrayDeque; import java.util.ArrayList; @@ -25,7 +29,11 @@ import java.util.Optional; import java.util.ServiceLoader; import java.util.Set; +import java.util.concurrent.Executors; import java.util.concurrent.LinkedBlockingDeque; +import java.util.concurrent.ScheduledExecutorService; +import java.util.concurrent.ScheduledFuture; +import java.util.concurrent.TimeUnit; import java.util.concurrent.atomic.AtomicBoolean; import java.util.function.Consumer; import java.util.function.Function; @@ -73,6 +81,7 @@ import io.quarkus.deployment.builditem.TestClassBeanBuildItem; import io.quarkus.deployment.builditem.TestClassPredicateBuildItem; import io.quarkus.runtime.LaunchMode; +import io.quarkus.runtime.configuration.DurationConverter; import io.quarkus.runtime.configuration.ProfileManager; import io.quarkus.runtime.test.TestHttpEndpointProvider; import io.quarkus.test.common.PathTestHelper; @@ -102,6 +111,7 @@ public class QuarkusTestExtension protected static final String TEST_LOCATION = "test-location"; protected static final String TEST_CLASS = "test-class"; + public static final String QUARKUS_TEST_HANG_DETECTION_TIMEOUT = "quarkus.test.hang-detection-timeout"; private static boolean failedBoot; @@ -124,8 +134,58 @@ public class QuarkusTestExtension private static DeepClone deepClone; //needed for @Nested private static Deque> currentTestClassStack = new ArrayDeque<>(); + private static ScheduledExecutorService hangDetectionExecutor; + private static Duration hangTimeout; + private static ScheduledFuture hangTaskKey; + private static final Runnable hangDetectionTask = new Runnable() { + + final AtomicBoolean runOnce = new AtomicBoolean(); + + @Override + public void run() { + if (!runOnce.compareAndSet(false, true)) { + return; + } + System.err.println("@QuarkusTest has detected a hang, as there has been no test activity in " + hangTimeout); + System.err.println("To configure this timeout use the " + QUARKUS_TEST_HANG_DETECTION_TIMEOUT + " config property"); + System.err.println("A stack track is below to help diagnose the potential hang"); + System.err.println("=== Stack Trace ==="); + ThreadInfo[] threads = ManagementFactory.getThreadMXBean().dumpAllThreads(true, true); + for (ThreadInfo info : threads) { + if (info == null) { + System.err.println(" Inactive"); + continue; + } + Thread.State state = info.getThreadState(); + System.err.println("Thread " + info.getThreadName() + ": " + state); + if (state == Thread.State.WAITING) { + System.err.println(" Waiting on " + info.getLockName()); + } else if (state == Thread.State.BLOCKED) { + System.err.println(" Blocked on " + info.getLockName()); + System.err.println(" Blocked by " + info.getLockOwnerName()); + } + System.err.println(" Stack:"); + for (StackTraceElement frame : info.getStackTrace()) { + System.err.println(" " + frame.toString()); + } + } + System.err.println("=== End Stack Trace ==="); + //we only every dump once + } + }; private ExtensionState doJavaStart(ExtensionContext context, Class profile) throws Throwable { + hangDetectionExecutor = Executors.newSingleThreadScheduledExecutor(); + String time = "10m"; + //config is not established yet + //we can only read from system properties + String sysPropString = System.getProperty(QUARKUS_TEST_HANG_DETECTION_TIMEOUT); + if (sysPropString != null) { + time = sysPropString; + } + hangTimeout = new DurationConverter().convert(time); + hangTaskKey = hangDetectionExecutor.schedule(hangDetectionTask, hangTimeout.toMillis(), TimeUnit.MILLISECONDS); + quarkusTestProfile = profile; Closeable testResourceManager = null; try { @@ -258,6 +318,14 @@ private ExtensionState doJavaStart(ExtensionContext context, Class entry : sysPropRestore.entrySet()) { - String val = entry.getValue(); - if (val == null) { - System.clearProperty(entry.getKey()); - } else { - System.setProperty(entry.getKey(), val); + try { + for (Map.Entry entry : sysPropRestore.entrySet()) { + String val = entry.getValue(); + if (val == null) { + System.clearProperty(entry.getKey()); + } else { + System.setProperty(entry.getKey(), val); + } } + tm.close(); + } finally { + hangDetectionExecutor.shutdown(); } - tm.close(); } try { TestClassIndexer.removeIndex(requiredTestClass); @@ -391,6 +463,7 @@ public void beforeEach(ExtensionContext context) throws Exception { if (isNativeTest()) { return; } + resetHangTimeout(); if (!failedBoot) { ClassLoader original = setCCL(runningQuarkusApplication.getClassLoader()); try { @@ -459,6 +532,7 @@ public void afterEach(ExtensionContext context) throws Exception { if (isNativeTest()) { return; } + resetHangTimeout(); if (!failedBoot) { popMockContext(); ClassLoader original = setCCL(runningQuarkusApplication.getClassLoader()); @@ -586,6 +660,7 @@ public void beforeAll(ExtensionContext context) throws Exception { if (isNativeTest()) { return; } + resetHangTimeout(); ensureStarted(context); if (runningQuarkusApplication != null) { pushMockContext(); @@ -625,6 +700,7 @@ public void interceptBeforeAllMethod(Invocation invocation, ReflectiveInvo invocation.proceed(); return; } + resetHangTimeout(); ensureStarted(extensionContext); if (failedBoot) { throwBootFailureException(); @@ -640,6 +716,7 @@ public T interceptTestClassConstructor(Invocation invocation, if (isNativeTest()) { return invocation.proceed(); } + resetHangTimeout(); ExtensionState state = ensureStarted(extensionContext); if (failedBoot) { throwBootFailureException(); @@ -796,6 +873,7 @@ public void interceptAfterAllMethod(Invocation invocation, ReflectiveInvoc private Object runExtensionMethod(ReflectiveInvocationContext invocationContext, ExtensionContext extensionContext) throws Throwable { + resetHangTimeout(); Method newMethod = null; ClassLoader old = setCCL(runningQuarkusApplication.getClassLoader()); @@ -850,6 +928,7 @@ private Object runExtensionMethod(ReflectiveInvocationContext invocation @Override public void afterAll(ExtensionContext context) throws Exception { + resetHangTimeout(); try { if (!isNativeTest() && (runningQuarkusApplication != null)) { popMockContext(); @@ -922,6 +1001,7 @@ public void run() { @Override public void close() { + resetHangTimeout(); if (closed.compareAndSet(false, true)) { ClassLoader old = Thread.currentThread().getContextClassLoader(); if (runningQuarkusApplication != null) { @@ -1045,4 +1125,11 @@ public void execute(BuildContext context) { return allCustomizers; } } + + private static void resetHangTimeout() { + if (hangTaskKey != null) { + hangTaskKey.cancel(false); + hangTaskKey = hangDetectionExecutor.schedule(hangDetectionTask, hangTimeout.toMillis(), TimeUnit.MILLISECONDS); + } + } }