Skip to content

Commit

Permalink
Add .debugBytecode() and .traceCategories() to QuarkusUnitTest
Browse files Browse the repository at this point in the history
To ease debugging of such tests.
  • Loading branch information
yrodiere committed Sep 12, 2024
1 parent e47fe96 commit 94176a8
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
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.

Check warning on line 2297 in docs/src/main/asciidoc/writing-extensions.adoc

View workflow job for this annotation

GitHub Actions / Linting with Vale

[vale] reported by reviewdog 🐶 [Quarkus.Headings] Use sentence-style capitalization in '2.18.2. Inspecting Generated/Transformed Classes in'. Raw Output: {"message": "[Quarkus.Headings] Use sentence-style capitalization in '2.18.2. Inspecting Generated/Transformed Classes in'.", "location": {"path": "docs/src/main/asciidoc/writing-extensions.adoc", "range": {"start": {"line": 2297, "column": 84}}}, "severity": "INFO"}

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

When <<testing-extensions,using `QuarkusUnitTest`>>,

Check warning on line 2302 in docs/src/main/asciidoc/writing-extensions.adoc

View workflow job for this annotation

GitHub Actions / Linting with Vale

[vale] reported by reviewdog 🐶 [Quarkus.TermsWarnings] Consider using 'might (for possibility)' or 'can (for ability)' rather than 'may' unless updating existing content that uses the term. Raw Output: {"message": "[Quarkus.TermsWarnings] Consider using 'might (for possibility)' or 'can (for ability)' rather than 'may' unless updating existing content that uses the term.", "location": {"path": "docs/src/main/asciidoc/writing-extensions.adoc", "range": {"start": {"line": 2302, "column": 8}}}, "severity": "WARNING"}
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,

Check warning on line 2322 in docs/src/main/asciidoc/writing-extensions.adoc

View workflow job for this annotation

GitHub Actions / Linting with Vale

[vale] reported by reviewdog 🐶 [Quarkus.SentenceLength] Try to keep sentences to an average of 32 words or fewer. Raw Output: {"message": "[Quarkus.SentenceLength] Try to keep sentences to an average of 32 words or fewer.", "location": {"path": "docs/src/main/asciidoc/writing-extensions.adoc", "range": {"start": {"line": 2322, "column": 18}}}, "severity": "INFO"}
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.

Check warning on line 2329 in docs/src/main/asciidoc/writing-extensions.adoc

View workflow job for this annotation

GitHub Actions / Linting with Vale

[vale] reported by reviewdog 🐶 [Quarkus.Fluff] Depending on the context, consider using 'Rewrite the sentence, or use 'must', instead of' rather than 'need to'. Raw Output: {"message": "[Quarkus.Fluff] Depending on the context, consider using 'Rewrite the sentence, or use 'must', instead of' rather than 'need to'.", "location": {"path": "docs/src/main/asciidoc/writing-extensions.adoc", "range": {"start": {"line": 2329, "column": 58}}}, "severity": "INFO"}

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

Check warning on line 2332 in docs/src/main/asciidoc/writing-extensions.adoc

View workflow job for this annotation

GitHub Actions / Linting with Vale

[vale] reported by reviewdog 🐶 [Quarkus.TermsWarnings] Consider using 'might (for possibility)' or 'can (for ability)' rather than 'may' unless updating existing content that uses the term. Raw Output: {"message": "[Quarkus.TermsWarnings] Consider using 'might (for possibility)' or 'can (for ability)' rather than 'may' unless updating existing content that uses the term.", "location": {"path": "docs/src/main/asciidoc/writing-extensions.adoc", "range": {"start": {"line": 2332, "column": 12}}}, "severity": "WARNING"}

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");

Check warning on line 2346 in docs/src/main/asciidoc/writing-extensions.adoc

View workflow job for this annotation

GitHub Actions / Linting with Vale

[vale] reported by reviewdog 🐶 [Quarkus.SentenceLength] Try to keep sentences to an average of 32 words or fewer. Raw Output: {"message": "[Quarkus.SentenceLength] Try to keep sentences to an average of 32 words or fewer.", "location": {"path": "docs/src/main/asciidoc/writing-extensions.adoc", "range": {"start": {"line": 2346, "column": 46}}}, "severity": "INFO"}
// ... test methods go here ...
}
----

Check warning on line 2351 in docs/src/main/asciidoc/writing-extensions.adoc

View workflow job for this annotation

GitHub Actions / Linting with Vale

[vale] reported by reviewdog 🐶 [Quarkus.TermsSuggestions] Depending on the context, consider using 'because' or 'while' rather than 'as'. Raw Output: {"message": "[Quarkus.TermsSuggestions] Depending on the context, consider using 'because' or 'while' rather than 'as'.", "location": {"path": "docs/src/main/asciidoc/writing-extensions.adoc", "range": {"start": {"line": 2351, "column": 3}}}, "severity": "INFO"}

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

This is handy to debug flaky tests that happen only in the CI environment, in particular,

Check warning on line 2355 in docs/src/main/asciidoc/writing-extensions.adoc

View workflow job for this annotation

GitHub Actions / Linting with Vale

[vale] reported by reviewdog 🐶 [Quarkus.Headings] Use sentence-style capitalization in '2.18.4. Multi-module Maven Projects and the Development Mode'. Raw Output: {"message": "[Quarkus.Headings] Use sentence-style capitalization in '2.18.4. Multi-module Maven Projects and the Development Mode'.", "location": {"path": "docs/src/main/asciidoc/writing-extensions.adoc", "range": {"start": {"line": 2355, "column": 64}}}, "severity": "INFO"}

Check warning on line 2355 in docs/src/main/asciidoc/writing-extensions.adoc

View workflow job for this annotation

GitHub Actions / Linting with Vale

[vale] reported by reviewdog 🐶 [Quarkus.HeadingPunctuation] Do not use end punctuation in headings. Raw Output: {"message": "[Quarkus.HeadingPunctuation] Do not use end punctuation in headings.", "location": {"path": "docs/src/main/asciidoc/writing-extensions.adoc", "range": {"start": {"line": 2355, "column": 64}}}, "severity": "INFO"}
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.

Check warning on line 2360 in docs/src/main/asciidoc/writing-extensions.adoc

View workflow job for this annotation

GitHub Actions / Linting with Vale

[vale] reported by reviewdog 🐶 [Quarkus.TermsWarnings] Consider using 'to' rather than 'in order to' unless updating existing content that uses the term. Raw Output: {"message": "[Quarkus.TermsWarnings] Consider using 'to' rather than 'in order to' unless updating existing content that uses the term.", "location": {"path": "docs/src/main/asciidoc/writing-extensions.adoc", "range": {"start": {"line": 2360, "column": 67}}}, "severity": "WARNING"}
Expand Down
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
Original file line number Diff line number Diff line change
Expand Up @@ -27,13 +27,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 @@ -137,6 +139,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 @@ -514,6 +522,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 @@ -718,6 +745,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 @@ -764,6 +805,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 @@ -850,6 +901,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 94176a8

Please sign in to comment.