Repository navigation
Logging configuration leaks from one test to the next #43180
Description
Describe the bug
While working on #43074 I noticed that when I set system properties related to logging (e.g. quarkus.logging."org.hibernate".level=TRACE) before a test using QuarkusUnitTest, then these properties still apply in test classes that execute afterwards -- even if I reset them after each test!
I thought "fair enough, setting system properties dynamically probably isn't recommended anyway".
But then I started doing something like this:
@RegisterExtension
static QuarkusUnitTest runner = new QuarkusUnitTest()
.withApplicationRoot((jar) -> jar
.addClass(MyMappedSuperclass.class)
.addClass(MyAbstractEntity.class)
.addClass(MyConcreteEntity.class)
.addClass(FieldAccessEnhancedDelegate.class))
.withConfigurationResource("application.properties")
.overrideConfigKey("quarkus.hibernate-orm.log.bind-parameters", "true");... which simply sets a Quarkus property related to logging (bind-parameters) in application.properties.
And again, that setting affected test classes that executed afterwards.
So, it seems to me QuarkusUnitTest leaks logging configuration from one test to the next... somehow.
QuarkusUnitTest being internal, it's not that bad, but what worries me more is the possibility that this leak could also happen in actual application tests, for example those that use a QuarkusTestProfile to enable tracing in one particular test only. I did not try that, but that's something we should investigate to decide how critical this leak is.
Expected behavior
Customizing log configuration in one test should not affect following test classes in the same run.
Actual behavior
Customizing log configuration in one test affects all following test classes in the same run.
How to Reproduce?
- Clone https://github.com/yrodiere/quarkus/tree/test-logging-config-leak (note it's branch
test-logging-config-leak, notmain) - Notice in the Git history that the logging config is modified in
PublicFieldAccessInheritanceTestthrough propertyquarkus.hibernate-orm.log.bind-parameters. - Notice in the Git history that the logging config is not modified in
LogBindParametersDefaultValueTest. - Build Quarkus locally.
- Run
./mvnw clean test -pl extensions/hibernate-orm/deployment -Dtest='PublicFieldAccessInheritanceTest,LogBindParametersDefaultValueTest' - Notice the test output for
LogBindParametersDefaultValueTestshows TRACE logs, even though we don't enable them in this test. - Notice
LogBindParametersDefaultValueTestfailed because of these unexpected logs.
Output of uname -a or ver
No response
Output of java -version
No response
Quarkus version or git rev
No response
Build tool (ie. output of mvnw --version or gradlew --version)
No response
Additional information
No response
Activity
quarkus-bot commentedon Sep 10, 2024
/cc @radcortez (config)
[-]Logging configuration leaks from one test to the next, even when using different configuration[/-][+]Logging configuration leaks from one test to the next[/+]radcortez commentedon Sep 10, 2024
Yes, this is probably related to #27996.
Unfortunately, we need to get a few things out of the way to fix this: #42986
mkouba commentedon Sep 11, 2024
@yrodiere Does it only apply to logging configuration or any config property in general?
yrodiere commentedon Sep 11, 2024
It applies to anything having an effect on logging, but only logging, from what I can see.
So
quarkus.logging.*, but alsoquarkus.hibernate-orm.log.bind-parameterswhich actually creates a build item that affects logging behavior.mkouba commentedon Sep 12, 2024
I think that in Quarkus the logging config/context is stored in a static variable and so for example if you change the category level per test you would need to reset the level to the previous value after the test. And this "reset" action could be pretty complex. Unless there's a way to capture the "snapshot" of the logging config and apply this snapshot afterwards 🤷.
CC @dmlloyd
yrodiere commentedon Sep 12, 2024
FWIW I worked around the issue for my particular use case by working directly with
Logger#setLevel; see uses ofsetLevelin https://github.com/quarkusio/quarkus/pull/43077/files .Of course this doesn't change anything for application developpers setting logging-related configuration properties on a per-test basis 🤷
You could alternatively just reset all levels to
nullafter an application shutdown in test mode, so that you can reapply the whole logging configuration from a clean slate on each application startup.yrodiere commentedon Sep 12, 2024
This makes me wonder whether dev mode is affected 🤔
mkouba commentedon Sep 12, 2024
This looks pretty useful 👍
dmlloyd commentedon Sep 12, 2024
There is more to logging than levels. Resetting all of logging is theoretically possible but probably pretty difficult. It might be easier to do/undo logging changes per test, for now.