Skip to content

Commit

Permalink
Merge pull request quarkusio#43077 from yrodiere/easier-debugging
Browse files Browse the repository at this point in the history 
Add .debugBytecode() and .traceCategories() to QuarkusUnitTest
  • Loading branch information
@gsmet
gsmet authored Sep 13, 2024
2 parents 629d89c + 94176a8 commit 283f8b1
Show file tree
Hide file tree
Showing 3 changed files with 143 additions and 37 deletions.
61 changes: 60 additions & 1 deletion docs/src/main/asciidoc/writing-extensions.adoc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -1983,7 +1983,7 @@ to initiate a scan for changed files.
Where extensions use an external service, adding a Dev Service can improve the user experience in development and test modes.
See xref:extension-writing-dev-service.adoc[how to write a Dev Service] for more details.


[[testing-extensions]]
=== Testing Extensions

Testing of Quarkus extensions should be done with the `io.quarkus.test.QuarkusUnitTest` JUnit 5 extension.
Expand Down Expand Up @@ -2296,6 +2296,65 @@ The property is also honored when running tests:

Analogously, you can use the `quarkus.debug.transformed-classes-dir` and `quarkus.debug.generated-sources-dir` properties to dump the relevant output.

[[dump-generated-transformed-classes-with-quarkusunittest]]
==== Inspecting Generated/Transformed Classes in `QuarkusUnitTest`

When <<testing-extensions,using `QuarkusUnitTest`>>,
as an alternative to <<dump-the-generated-classes-to-the-file-system,setting `quarkus.debug.*-dir` manually>>,
you may simply call `QuarkusUnitTest#debugBytecode`:

[source,java]
----
public class MyTest {
@RegisterExtension
static QuarkusUnitTest runner = new QuarkusUnitTest()
.withApplicationRoot((jar) -> jar
.addClass(MyEntity.class))
.debugBytecode(true);
// ... test methods go here ...
}
----

This will automatically set up these configuration properties so that classes/sources
are dumped to `target/debug`, for that test class only,
in a subdirectory that is unique to each test execution.
See the javadoc of `QuarkusUnitTest#debugBytecode` for details.

This is handy to debug flaky tests that happen only in the CI environment, in particular;
for example the GitHub Actions CI at https://github.com/quarkusio/quarkus/
is set up so that such `target/debug` directories are
collected into build artifacts available for download after each CI run.

[[troubleshooting-trace-logs]]
==== Enabling trace logs for a particular test only

When <<testing-extensions,using `QuarkusUnitTest`>>,
if you need to enable trace logs for a particular test class,
you may simply call `QuarkusUnitTest#traceCategories` and pass the logging categories in argument:

[source,java]
----
public class MyTest {
@RegisterExtension
static QuarkusUnitTest runner = new QuarkusUnitTest()
.withApplicationRoot((jar) -> jar
.addClass(MyEntity.class))
.traceCategories("org.hibernate", "io.quarkus.hibernate", "io.quarkus.panache");
// ... test methods go here ...
}
----

See the javadoc of `QuarkusUnitTest#traceCategories` for details.

This is handy to debug flaky tests that happen only in the CI environment, in particular,
as this will only increase the verbosity of logs in the particular test where the option is enabled.

==== Multi-module Maven Projects and the Development Mode

It's not uncommon to develop an extension in a multi-module Maven project that also contains an "example" module.
Expand Down
38 changes: 2 additions & 36 deletions ...ava/io/quarkus/hibernate/orm/applicationfieldaccess/PublicFieldAccessInheritanceTest.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -2,11 +2,6 @@

import static org.assertj.core.api.Assertions.assertThat;

import java.util.List;
import java.util.Map;
import java.util.UUID;
import java.util.logging.LogManager;

import jakarta.inject.Inject;
import jakarta.persistence.Entity;
import jakarta.persistence.EntityManager;
Expand All @@ -21,7 +16,6 @@
import jakarta.transaction.UserTransaction;

import org.hibernate.Hibernate;
import org.jboss.logmanager.Level;
import org.junit.jupiter.api.Test;
import org.junit.jupiter.api.extension.RegisterExtension;

Expand All @@ -33,19 +27,6 @@
*/
public class PublicFieldAccessInheritanceTest {

// FIXME Temporary debug options for https://github.com/quarkusio/quarkus/issues/42479
// Needs to be set very early (e.g. as system properties) in order to affect the build;
// see https://quarkusio.zulipchat.com/#narrow/stream/187038-dev/topic/Build.20logs
private static final Map<String, String> DEBUG_PROPERTIES = Map.of(
"quarkus.debug.transformed-classes-dir", "target/debug/${testRunId}/transformed-classes",
"quarkus.debug.generated-classes-dir", "target/debug/${testRunId}/generated-classes");
// FIXME Temporary trace categories for https://github.com/quarkusio/quarkus/issues/42479
// Needs to be set very early (e.g. programmatically) in order to affect the build;
// needs to be set programmatically in order to not leak to other tests.
// See https://quarkusio.zulipchat.com/#narrow/stream/187038-dev/topic/Build.20logs
// See https://github.com/quarkusio/quarkus/issues/43180
private static final List<String> TRACE_CATEGORIES = List.of("org.hibernate", "io.quarkus.hibernate", "io.quarkus.panache");

@RegisterExtension
static QuarkusUnitTest runner = new QuarkusUnitTest()
.withApplicationRoot((jar) -> jar
Expand All @@ -61,23 +42,8 @@ public class PublicFieldAccessInheritanceTest {
// It's not necessary anyway as the only effect of this config property is to change
// the logging level for a specific "org.hibernate.something" category, which we already do below.
//.overrideConfigKey("quarkus.hibernate-orm.log.bind-parameters", "true")
.setBeforeAllCustomizer(() -> {
// Used to differentiate reruns of flaky tests in Maven
var testRunId = PublicFieldAccessInheritanceTest.class + "/" + UUID.randomUUID();
System.out.println("Test run ID: " + testRunId);
DEBUG_PROPERTIES.forEach((key, value) -> System.setProperty(key, value.replace("${testRunId}", testRunId)));
for (String category : TRACE_CATEGORIES) {
LogManager.getLogManager().getLogger(category)
.setLevel(Level.TRACE);
}
})
.setAfterAllCustomizer(() -> {
DEBUG_PROPERTIES.keySet().forEach(System::clearProperty);
for (String category : TRACE_CATEGORIES) {
LogManager.getLogManager().getLogger(category)
.setLevel(null);
}
});
.debugBytecode(true)
.traceCategories("org.hibernate", "io.quarkus.hibernate", "io.quarkus.panache");

@Inject
EntityManager em;
Expand Down
81 changes: 81 additions & 0 deletions test-framework/junit5-internal/src/main/java/io/quarkus/test/QuarkusUnitTest.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -23,13 +23,15 @@
import java.util.ServiceLoader;
import java.util.Timer;
import java.util.TimerTask;
import java.util.UUID;
import java.util.function.Consumer;
import java.util.function.Predicate;
import java.util.function.Supplier;
import java.util.logging.Handler;
import java.util.logging.LogManager;
import java.util.logging.LogRecord;

import org.jboss.logmanager.Level;
import org.jboss.logmanager.Logger;
import org.jboss.shrinkwrap.api.ShrinkWrap;
import org.jboss.shrinkwrap.api.exporter.ExplodedExporter;
Expand Down Expand Up @@ -134,6 +136,12 @@ public class QuarkusUnitTest

private List<Consumer<QuarkusBootstrap.Builder>> bootstrapCustomizers = new ArrayList<>();

private boolean debugBytecode = false;
private List<String> traceCategories = new ArrayList<>();

private Map<String, String> systemPropertiesToRestore = new HashMap<>();
private Map<String, java.util.logging.Level> loggerLevelsToRestore = new HashMap<>();

public QuarkusUnitTest setExpectedException(Class<? extends Throwable> expectedException) {
return setExpectedException(expectedException, false);
}
Expand Down Expand Up @@ -520,6 +528,25 @@ public void beforeAll(ExtensionContext extensionContext) throws Exception {
if (beforeAllCustomizer != null) {
beforeAllCustomizer.run();
}
if (debugBytecode) {
// Use a unique ID to avoid overriding dumps between test classes (and re-execution of flaky tests).
var testRunId = extensionContext.getRequiredTestClass().getName() + "/" + UUID.randomUUID();
System.out.println("[QuarkusUnitTest] Debug dumps enabled. Test run ID: " + testRunId);
// This needs to be set as system properties; see BootstrapDebug.java.
// Note these paths are considered standard and may be taken advantage of in Quarkus CI (to collect dumps).
overrideSystemProperty("quarkus.debug.transformed-classes-dir",
"target/debug/" + testRunId + "/transformed-classes");
overrideSystemProperty("quarkus.debug.generated-classes-dir", "target/debug/" + testRunId + "/generated-classes");
overrideSystemProperty("quarkus.debug.generated-sources-dir", "target/debug/" + testRunId + "/generated-sources");
}
if (!traceCategories.isEmpty()) {
// This needs to be set very early (e.g. as system properties) in order to affect the build;
// needs to be set programmatically in order to not leak to other tests (for some reason?).
// See https://quarkusio.zulipchat.com/#narrow/stream/187038-dev/topic/Build.20logs
for (String category : traceCategories) {
overrideLoggerLevel(category, Level.TRACE);
}
}
originalClassLoader = Thread.currentThread().getContextClassLoader();
originalHandlers = rootLogger.getHandlers();
rootLogger.addHandler(inMemoryLogHandler);
Expand Down Expand Up @@ -724,6 +751,20 @@ private Throwable unwrapException(Throwable cause) {
return cause;
}

private void overrideSystemProperty(String key, String value) {
// IMPORTANT: Not logging the value in case it's a secret.
System.out.printf("[QuarkusUnitTest] Overriding system property '%s'%n", key);
systemPropertiesToRestore.putIfAbsent(key, System.getProperty(key));
System.setProperty(key, value);
}

private void overrideLoggerLevel(String category, Level level) {
System.out.printf("[QuarkusUnitTest] Overriding logger category '%s'; setting level '%s'%n", category, level);
var logger = LogManager.getLogManager().getLogger(category);
loggerLevelsToRestore.putIfAbsent(category, logger.getLevel());
logger.setLevel(level);
}

@Override
public void afterAll(ExtensionContext extensionContext) throws Exception {
actualTestClass = null;
Expand Down Expand Up @@ -770,6 +811,16 @@ public void afterAll(ExtensionContext extensionContext) throws Exception {
if (afterAllCustomizer != null) {
afterAllCustomizer.run();
}
systemPropertiesToRestore.forEach((key, previousValue) -> {
if (previousValue == null) {
System.clearProperty(key);
} else {
System.setProperty(key, previousValue);
}
});
systemPropertiesToRestore.clear();
loggerLevelsToRestore.forEach((category, previousLevel) -> Logger.getLogger(category).setLevel(previousLevel));
loggerLevelsToRestore.clear();
ClearCache.clearCaches();
TestConfigUtil.cleanUp();
}
Expand Down Expand Up @@ -863,6 +914,36 @@ public QuarkusUnitTest overrideRuntimeConfigKey(final String propertyKey, final
return this;
}

/**
* Controls bytecode-related debug dumping.
* <p>
* When enabled, each Quarkus startup will have configuration properties
* such as {@code quarkus.debug.generated-classes-dir} set
* so that generated code gets dumped in {@code target/debug},
* within a unique subdirectory for each test execution.
* <p>
* Look at the logs of a particular test to identify the corresponding dump directory.
*
* @param debugBytecode {@code true} if debug should be enabled
* @return {@code this}, for method chaining.
*/
public QuarkusUnitTest debugBytecode(boolean debugBytecode) {
this.debugBytecode = debugBytecode;
return this;
}

/**
* Enables trace logs for the given categories,
* during both build and runtime.
*
* @param categories The categories for which to enable trace logging.
* @return {@code this}, for method chaining.
*/
public QuarkusUnitTest traceCategories(String... categories) {
Collections.addAll(this.traceCategories, categories);
return this;
}

@Override
public boolean supportsParameter(ParameterContext parameterContext, ExtensionContext extensionContext)
throws ParameterResolutionException {
Expand Down

0 comments on commit 283f8b1

Please sign in to comment.