Gradle tests (with JBoss LogManager setup) output duplicate unformatted messages

[kdubb]

Describe the bug

When Gradle tests are setup to use the JBoss LogManager (as suggested in the test logging guide using systemProperty "java.util.logging.manager", "org.jboss.logmanager.LogManager"). Gradle will output unformatted raw messages to stdout during testing.

For example, this log statement in an application:

Log.errorf("Hello %s!", "World");

will produce the following output during ./gradlew (build|test):

> Task :quarkusGenerateCode
preparing quarkus application

> Task :quarkusGenerateCodeTests
preparing quarkus application
Hello %s!

BUILD SUCCESSFUL in 3s
6 actionable tasks: 6 executed

It should be noted that Gradle hides stdout/stderr from tests by default. So the Hello %s is a duplicate, if you look at the stdout output of the actual test you will see a proper log line with the message Hello World!.

Expected behavior

Log messages should be output once (and never be unformatted) during build and/or teest.

Actual behavior

Log messages are duplicated and unformatted during build and/or test.

How to Reproduce?

code-with-quarkus.zip

Output of uname -a or ver

MacOS 12.1

Output of java -version

Java 17

GraalVM version (if different from Java)

No response

Quarkus version or git rev

2.6.2.Final

Build tool (ie. output of mvnw --version or gradlew --version)

Gradle 7.3.3

Additional information

No response

[quarkus-bot]

/cc @glefloch, @quarkusio/devtools @dmlloyd

[famod]

Strange, Log.errorv("Hello {0}!", "World"); works.

/cc @Ladicek

PS: This also happens with current main.

[glefloch]

Test reports are ok. I think this comes from the gradle test task which tries to output logging but shouldn't. We can deactivate this behavior directly in the plugin.

[kdubb]

I think so too. Gradle seems to try and capture logging (by installing it's own JUL handler) and apparently has no way of disabling this feature. This feature seems pretty needless (idiotic?) considering they already capture stdout/stderr and that's where JUL logs end up by default.

[glefloch]

I tried differend configuration but nothing change. I asked a question on their forum.

[sgrissom-rxss]

@glefloch did anything come of this from the Gradle forums? I tried searching there as well but didn't find any related conversations.

edit: found the forum question and there was no response :/

[kdubb]

@glefloch With 3.5.3 (upgrading from 3.3.x) we are now seeing these duplicated, unformatted, log messages all the time, without installing the JBoss LogManager in the Gradle tests. It seems Quarkus is now adding/initializing this by default (although I could not figure out where this change happened).

Previously, we just were not adding the JBoss LogManager (the messages were mostly useless without formatting) and this worked around the issue; although did miss printing configured test logging (e.g. errors). With Updated Quarkus we needed a fix and did a bit of investigation and came up with a workaround.

Basically Gradle 8.4 is adding a SLF4JBrigeHandler to the root logger (aka "") of the current JUL LogManager (which is the JBoss LogManager). Passing ExtLogRecord instances to this cause it to print the unformatted message.

The fix/workaround is to walkthrough the list of handler's in the root logger and wrap any SLF4JBridgeHandler instances with a handler that first formats the log message. For ease, I did this in a JUnit5 extension.

Here's the extension (Kotlin):

class LoggingFixExtension: BeforeAllCallback {
  override fun beforeAll(context: ExtensionContext) {
    val logger = LogManager.getLogManager().getLogger("")
    val handlers = logger.handlers.clone()
    handlers.forEach {
      if (it.javaClass.simpleName == "SLF4JBridgeHandler") {
        logger.removeHandler(it)
        logger.addHandler(FormattingFixHandler(it))
      }
    }
  }
}

Here's the handler (Kotlin):

class FormattingFixHandler(val wrapped: Handler): Handler() {
  override fun publish(record: LogRecord) {
    @Suppress("DEPRECATION")
    val preparedRecord =
      if (record is ExtLogRecord && record.formatStyle != ExtLogRecord.FormatStyle.NO_FORMAT) {
        val formatted = ExtLogRecord(record)
        formatted.setMessage(record.formattedMessage, ExtLogRecord.FormatStyle.NO_FORMAT)
        formatted
      } else {
        record
      }
    wrapped.publish(preparedRecord)
  }
  override fun flush() {
    wrapped.flush()
  }
  override fun close() {
    wrapped.close()
  }
}

Note: It uses the deprecated ExtLogRecord.formattedMessage, which is deprecated with the note that the "formatter" should be used. I currently don't know what where the "formatter" is and will probably investigate further.

This is working for now but there's a couple ways this might be tackled by Quarkus to provide a proper logging experience in Gradle.

1. Investigate and fix SLF4JBridgeHandler improper handling of ExtLogRecord.

This seems like the most obvious fix. SLF4JBridgeHandler appears to be a standard SLF4J class and it seems JBoss Logging should work with it, but I don't know how it's supposed to work (and the JBoss Logging project has issues disabled).

2. Automatically apply a similar fix during testing.

Quarkus should be able to apply this fix. It could be as simple as shipping the above JUnit 5 extension and using its service loader registration functionality to add the handler (that's actually how we are installing it currently).

[kdubb]

FYI... All the above workaround does is fix the formatting of the messages. The messages are logged "bare" (no level, thread, etc.). It's as if somebody did System.out.println with the LogRecord.message.

I'm not sure exactly what Gradle is supposed to be printing, it might be exactly that or it might be that the log record is still being mishandled.

[dmlloyd]

I spent the morning digging through Gradle sources trying to find some way to disable this behavior, or work around it, with no luck; instead, I'm trying an approach to make the JBoss LogManager more friendly towards "legacy" handlers/formatters.

See jboss-logging/jboss-logmanager#449 for more info.

[kdubb]

That's great! From looking at the code this is essentially my workaround implemented directly via LogManager, correct?

Asking, cause this would validate my workaround as being "correct" until this lands in Quarkus.

[dmlloyd]

Yes, essentially, with the added benefit that it will "fix" other handlers as well.

[dmlloyd]

The upstream patch is merged. I will ask James for a logmanager release as soon as jboss-parent is released (unrelated issue), which in turn is depending on a Surefire release. So, hopefully soon 🥲

[kdubb]

Thanks for the help! I'm sure many Gradle users out there will praise this haha