Quarkus: Log Level configuration not working in Unit Tests

[andreas-eberle]

Describe the bug
When running unit tests (not @QuarkusTest) of a quarkus project, only severe log messages are printed, no matter what quarkus.log.level is configured. This can be reproduced with the reproducer code below or any fresh Kotlin Gradle Quarkus project created with code.quarkus.io.

E.g. if I run the following test

import org.junit.jupiter.api.Test
import java.util.logging.Logger

class ExampleLoggingTest {

    private val logger = Logger.getLogger(ExampleLoggingTest::class.java.name)

    @Test
    fun testHelloEndpoint() {
        logger.severe { "Log severe" }
        logger.info { "Log info" }
        logger.fine { "Log fine" }
        logger.finest { "Log finest" }
    }
}

with an application.properties file like this:

quarkus.log.level=TRACE

Only the following log message is printed:

Log severe

When I remove the following from the build.gradle file

test {
    systemProperty "java.util.logging.manager", "org.jboss.logmanager.LogManager"
}

I then also get the INFO log and the format changes. The result is

Juli 31, 2020 9:13:29 AM org.acme.ExampleLoggingTest testHelloEndpoint
SEVERE: Log severe
Juli 31, 2020 9:13:29 AM org.acme.ExampleLoggingTest testHelloEndpoint
INFO: Log info

When running the same test as a @QuarkusTest, the logging works as expected. Still, unit tests are an important part of tests and function the same way.

Expected behavior
All log messages with a level higher than the one specified in the application.properties file should be printed in unit tests.

Actual behavior
Only severe messages are logged by default and only severe plus info messages are logged when removing the test {...} block from the build.gradle file.

To Reproduce
Steps to reproduce the behavior:

1. Download reproducer project and unzip it (or add the test shown above to any plain Quarkus Kotlin Gradle project from code.quarkus.io)
   2020-07-31_tests-logging.zip
2. Run ./gradlew check
3. Only the severe message is shown.

Configuration

quarkus.log.level=TRACE

Environment (please complete the following information):

• Windows 10
  
  
  
  • Quarkus 1.6.1, 1.5.2, 1.4.1 (others not tested)
  
  
  • Kotlin
  
  
  • OpenJDK 11
  
  

[geoand]

I am a little confused to be honest... Why do you expect quarkus.log.level to work in a plain old unit test?
Quarkus configuration only works with Quarkus applications

[andreas-eberle]

How can I get the logging to work in the unit test? I thought this should work because unit tests are a normal part of a Quarkus project and thus I'd expect them to run and feel like any other test in a Quarkus project. I understand that unit tests are not a Quarkus feature but I think Quarkus should make them work and feel like other Quarkus stuff in a Quarkus project to make things consistent and understandable for users.

[geoand]

The thing is that Quarkus can't control code that doesn't involve it. When do you use a Quarkus test and you set quarkus.log.level a lot of stuff happens to make that work.
When Quarkus does not come into play, then it's just another property (like foo.bar).

In unit tests the way to configure logging is via the standard logging configuration - Quarkus specific things won't work.

[andreas-eberle]

It would be nice to add some documentation on how to get logging working in junit tests when testing quarkus code. I think this should be added to the Quarkus testing guide. At the moment unit tests aren't mentioned there.

[andreas-eberle]

Maybe it could be an idea to have something like a @QuarkusUnitTest annotation only setting up basic stuff like logging and not starting the whole server. I still think Quarkus should aim to make unit tests work the same way full-blown Quarkus tests work to provide a complete user experience.

[geoand]

The problem with that is that different folks would probably expect different things.

[andreas-eberle]

I think it would be better to implement a reasonable working default than not having it work by default at all.

Currently you can write some QuarkusTests and some unit tests alongside each other and run them in the same step (e.g. with ./gradlew check). However one of them shows logs as expected and the other doesn't. From a user perspective, it is not clear why you would need to do something special for unit tests. Especially since nothing is noted in the documentation.

Maybe the quarkus gradle/maven plugins can be used to convert the quarkus logging config to the required config for normal unit tests?

[geoand]

I disagree that anything should be done, otherwise you would be going around trying to do anything that touches with Quarkus even a little.

But that is only my opinion :). I propose you send an email to the quarkus-dev mailing list explaining the situation and what you propose.

[famod]

Well, IMHO this is definitely a blind spot in Quarkus projects. See also: #7696

In my current project we also have yet to find out how to get proper log output from plain Junit5 tests.
Once I/we find a good way I'd come up with a documentation PR.

[andreas-eberle]

@famod: I was able to get the log outputs by changing the test task in the gradle file to

 test {
         systemProperty 'java.util.logging.config.file', "${projectDir}/src/test/resources/logging.properties"
 }

And I created a logging.properties file in the rest/resources directory with the following contents:

.level=INFO
com.my.package.level=FINEST
#
handlers=java.util.logging.ConsoleHandler
#
java.util.logging.ConsoleHandler.level=FINEST
java.util.logging.ConsoleHandler.formatter=java.util.logging.SimpleFormatter
java.util.logging.SimpleFormatter.format=[%1$tF %1$tT] [%4$-7s] %5$s %n

I hope this can help you.

[famod]

@andreas-eberle Thanks a lot for this! I'll try that.

[famod]

@andreas-eberle For this to work, java.util.logging.manager must _not_ be set to org.jboss.logmanager.LogManager, right?

That's a bit unfortunate since this will then "break" logging in QuarkusTests.

[zerocode]

@famod

Did you find a work around for this?