FORMAT_FAILURE when using Log.error(Object,Throwable)

[MaxFichtelmann]

Describe the bug

Hi, I stumbled across this bug, when an exception message contained braces and Log.error(e.getMessage(), e) produced unexpected output instead of logging the message and stacktrace.

Downgrading to quarkus 3.14.2 results in the expected behaviour - 3.14.3 fails.

Edit: upon closer inspection this only happens in dev-mode - the behaviour of the built artifact is fine.

Expected behavior

Message and Stacktrace should be logged

Actual behavior

The following stacktrace is printed:

LogManager error of type FORMAT_FAILURE: Formatting error
java.lang.IllegalArgumentException: Unmatched braces in the pattern.
        at java.base/java.text.MessageFormat.applyPattern(MessageFormat.java:540)
        at java.base/java.text.MessageFormat.<init>(MessageFormat.java:382)
        at java.base/java.text.MessageFormat.format(MessageFormat.java:882)
        at org.jboss.logmanager.ExtFormatter.formatMessageLegacy(ExtFormatter.java:133)
        at org.jboss.logmanager.ExtFormatter.formatMessage(ExtFormatter.java:96)
        at org.jboss.logmanager.formatters.ColorPatternFormatter.formatMessage(ColorPatternFormatter.java:129)
        at org.jboss.logmanager.formatters.Formatters$16.renderRaw(Formatters.java:832)
        at org.jboss.logmanager.formatters.Formatters$JustifyingFormatStep.render(Formatters.java:227)
        at org.jboss.logmanager.formatters.ColorPatternFormatter$ColorStep.render(ColorPatternFormatter.java:152)
        at org.jboss.logmanager.formatters.MultistepFormatter.format(MultistepFormatter.java:90)
        at org.jboss.logmanager.ExtFormatter$Delegating.format(ExtFormatter.java:196)
        at org.jboss.logmanager.ExtFormatter.format(ExtFormatter.java:58)
        at org.jboss.logmanager.handlers.WriterHandler.doPublish(WriterHandler.java:52)
        at org.jboss.logmanager.ExtHandler.publish(ExtHandler.java:88)
        at io.quarkus.deployment.logging.LoggingResourceProcessor$2.accept(LoggingResourceProcessor.java:471)
        at io.quarkus.deployment.logging.LoggingResourceProcessor$2.accept(LoggingResourceProcessor.java:406)
        at io.quarkus.runtime.logging.LoggingSetupRecorder$7.publish(LoggingSetupRecorder.java:570)
        at org.jboss.logmanager.ExtHandler.publishToNestedHandlers(ExtHandler.java:138)
        at io.quarkus.bootstrap.logging.QuarkusDelayedHandler.activate(QuarkusDelayedHandler.java:292)
        at io.quarkus.bootstrap.logging.QuarkusDelayedHandler.setHandlers(QuarkusDelayedHandler.java:189)
        at io.quarkus.runtime.logging.LoggingSetupRecorder.initializeLogging(LoggingSetupRecorder.java:255)
        at io.quarkus.deployment.steps.LoggingResourceProcessor$setupLoggingRuntimeInit2024815463.deploy_0(Unknown Source)
        at io.quarkus.deployment.steps.LoggingResourceProcessor$setupLoggingRuntimeInit2024815463.deploy(Unknown Source)
        at io.quarkus.runner.ApplicationImpl.doStart(Unknown Source)
        at io.quarkus.runtime.Application.start(Application.java:101)
        at io.quarkus.runtime.ApplicationLifecycleManager.run(ApplicationLifecycleManager.java:119)
        at io.quarkus.runtime.Quarkus.run(Quarkus.java:71)
        at io.quarkus.runtime.Quarkus.run(Quarkus.java:44)
        at io.quarkus.runtime.Quarkus.run(Quarkus.java:124)

How to Reproduce?

This can be reproduced with the following startup bean:

package org.acme;

import io.quarkus.logging.Log;
import io.quarkus.runtime.Startup;
import jakarta.annotation.PostConstruct;

@Startup
public class Start
{
    @PostConstruct
    public void onStart()
    {
        Log.info( "{", new Exception() );
    }
}

Output of uname -a or ver

No response

Output of java -version

No response

Quarkus version or git rev

3.14.3 - 3.16.3

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

No response

Additional information

No response

[phillip-kruger]

@gastaldi can you help ?

[gastaldi]

@jamezp is that intentional or could it be considered a bug?

[gsmet]

I think it's related to the new "let's point to the problematic code in the stack trace" feature.

@dmlloyd already fixed some of the issues in this patch: 7e6c529 .

But I suppose in the case of NO_FORMAT, we should also escape the message.

That being said, I remember @dmlloyd was quite unhappy about the approach so maybe it's time to go for a cleaner one. @dmlloyd maybe you could share what you had in mind? Someone might be interested in implementing it.

We will need a small fix for the backport though but I would very much like us to clean this up for the future if we can.

[jamezp]

Yeah, this doesn't look like it's coming from the log manager. I'm not able to reproduce this outside of Quarkus.

[dmlloyd]

I'm able to reproduce the problem, but what I'm grappling with is that I don't see why the problem doesn't occur outside of Quarkus. The code path seems very clear to me; the jboss-logging logger calls org.jboss.logmanager.Logger#log(java.lang.String, java.util.logging.Level, java.lang.String, java.lang.Throwable) which sets the format to MESSAGE_FORMAT instead of NO_FORMAT. There is no intervening Quarkus code at this point.

Here's the partial stack trace which shows what's happening more clearly (the above trace shows the problem during log message replay so some of the interesting stack isn't visible there):

java.util.logging.ErrorManager: 1: Nested handler publication threw an exception
java.lang.IllegalArgumentException: Unmatched braces in the pattern.
	at java.base/java.text.MessageFormat.applyPattern(MessageFormat.java:540)
	at java.base/java.text.MessageFormat.<init>(MessageFormat.java:382)
	at java.base/java.text.MessageFormat.format(MessageFormat.java:882)
	at org.jboss.logmanager.ExtFormatter.formatMessageLegacy(ExtFormatter.java:133)
	at org.jboss.logmanager.ExtFormatter.formatMessage(ExtFormatter.java:96)
	at io.quarkus.devui.runtime.logstream.JsonFormatter.toJsonObject(JsonFormatter.java:30)
	at io.quarkus.devui.runtime.logstream.MutinyLogHandler.doPublish(MutinyLogHandler.java:39)
	at org.jboss.logmanager.ExtHandler.publish(ExtHandler.java:88)
	at org.jboss.logmanager.ExtHandler.publishToNestedHandlers(ExtHandler.java:125)
	at io.quarkus.bootstrap.logging.QuarkusDelayedHandler.doPublish(QuarkusDelayedHandler.java:81)
	at org.jboss.logmanager.ExtHandler.publish(ExtHandler.java:88)
	at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:438)
	at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:480)
	at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:480)
	at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:480)
	at org.jboss.logmanager.Logger.logRaw(Logger.java:1089)
	at org.jboss.logmanager.Logger.log(Logger.java:1052)
	at org.jboss.logmanager.Logger.log(Logger.java:1064) // <== we set the format to `MESSAGE_FORMAT` here
	at org.jboss.logging.JBossLogManagerLogger.doLog(JBossLogManagerLogger.java:43)
	at org.jboss.logging.Logger.info(Logger.java:967)
	at org.acme.Start.onStart(Start.java:13)

[dmlloyd]

OK I think I found the difference; the ad-hoc handlers created by Quarkus do not extend ExtHandler so everything gets forced back into MessageFormat. I'm still doing a little follow-up research but I think that'll end up being the fix.

[geoand]

@dmlloyd should we merge #44565 to close this?

[dmlloyd]

IMO yes. If the bug isn't fully fixed, it will be after the log manager release in a few days.

[geoand]

Merged it, thanks!