Logging configuration leaks from one test to the next

[yrodiere]

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?

1. Clone https://github.com/yrodiere/quarkus/tree/test-logging-config-leak (note it's branch test-logging-config-leak, not main)
2. Notice in the Git history that the logging config is modified in PublicFieldAccessInheritanceTest through property quarkus.hibernate-orm.log.bind-parameters.
3. Notice in the Git history that the logging config is not modified in LogBindParametersDefaultValueTest.
4. Build Quarkus locally.
5. Run ./mvnw clean test -pl extensions/hibernate-orm/deployment -Dtest='PublicFieldAccessInheritanceTest,LogBindParametersDefaultValueTest'
6. Notice the test output for LogBindParametersDefaultValueTest shows TRACE logs, even though we don't enable them in this test.
7. Notice LogBindParametersDefaultValueTest failed 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

[quarkus-bot[bot]]

/cc @radcortez (config)

[radcortez]

Yes, this is probably related to https://github.com/quarkusio/quarkus/issues/27996.

Unfortunately, we need to get a few things out of the way to fix this: https://github.com/quarkusio/quarkus/issues/42986

[mkouba]

@yrodiere Does it only apply to logging configuration or any config property in general?

[yrodiere]

@yrodiere Does it only apply to logging configuration or any config property in general?

It applies to anything having an effect on logging, but only logging, from what I can see.

So quarkus.logging.*, but also quarkus.hibernate-orm.log.bind-parameters which actually creates a build item that affects logging behavior.

[mkouba]

@yrodiere Does it only apply to logging configuration or any config property in general?

It applies to anything having an effect on logging, but only logging, from what I can see.

So quarkus.logging.*, but also quarkus.hibernate-orm.log.bind-parameters which actually creates a build item that affects logging behavior.

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 :shrug:.

CC @dmlloyd

[yrodiere]

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.

FWIW I worked around the issue for my particular use case by working directly with Logger#setLevel; see uses of setLevel in 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 :shrug:

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 🤷.

You could alternatively just reset all levels to null after an application shutdown in test mode, so that you can reapply the whole logging configuration from a clean slate on each application startup.

[yrodiere]

You could alternatively just reset all levels to null after an application shutdown in test mode

This makes me wonder whether dev mode is affected :thinking:

[mkouba]

FWIW I worked around the issue for my particular use case by working directly with Logger#setLevel; see uses of setLevel in https://github.com/quarkusio/quarkus/pull/43077/files .

This looks pretty useful :+1:

[dmlloyd]

You could alternatively just reset all levels to null after an application shutdown in test mode, so that you can reapply the whole logging configuration from a clean slate on each application startup.

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.