FORMAT_FAILURE when using Log.errorf or Log.infof with throwable, message and string parameter containing { #45444

Skrethel · 2025-01-08T14:15:18Z

Describe the bug

Reproducible on Quarkus 3.13.0 and 3.17.5 by adding following log message. Parameter must contain "{" for error to reproduce.

Log.infof(new RuntimeException("Not important"), "Hello %s", "{world}");

Expected behavior

Quarkus should log specified message with the stacktrace from provided throwable.

Actual behavior

Quarkus throws following error

LogManager error of type FORMAT_FAILURE: Formatting error
java.lang.IllegalArgumentException: can't parse argument number: world
        at java.base/java.text.MessageFormat.makeFormat(MessageFormat.java:1485)
        at java.base/java.text.MessageFormat.applyPattern(MessageFormat.java:512)
        at java.base/java.text.MessageFormat.<init>(MessageFormat.java:383)
        at java.base/java.text.MessageFormat.format(MessageFormat.java:883)
        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:54)
        at org.jboss.logmanager.ExtHandler.publish(ExtHandler.java:88)
        at io.quarkus.deployment.logging.LoggingResourceProcessor$2.accept(LoggingResourceProcessor.java:485)
        at io.quarkus.deployment.logging.LoggingResourceProcessor$2.accept(LoggingResourceProcessor.java:420)
        at io.quarkus.runtime.logging.LoggingSetupRecorder$7.publish(LoggingSetupRecorder.java:621)
        at org.jboss.logmanager.ExtHandler.publishToNestedHandlers(ExtHandler.java:138)
        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.LoggerNode.publish(LoggerNode.java:480)
        at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:480)
        at org.jboss.logmanager.Logger.logRaw(Logger.java:921)
        at org.jboss.logmanager.Logger.log(Logger.java:884)
        at org.jboss.logging.JBossLogManagerLogger.doLogf(JBossLogManagerLogger.java:56)
        at org.jboss.logging.Logger.infof(Logger.java:1189)
        at org.acme.getting.started.GreetingResource.hello(GreetingResource.java:26)
        at org.acme.getting.started.GreetingResource$quarkusrestinvoker$hello_e747664148511e1e5212d3e0f4b40d45c56ab8a1.invoke(Unknown Source)
        at org.jboss.resteasy.reactive.server.handlers.InvocationHandler.handle(InvocationHandler.java:29)
        at io.quarkus.resteasy.reactive.server.runtime.QuarkusResteasyReactiveRequestContext.invokeHandler(QuarkusResteasyReactiveRequestContext.java:141)
        at org.jboss.resteasy.reactive.common.core.AbstractResteasyReactiveContext.run(AbstractResteasyReactiveContext.java:147)
        at io.quarkus.vertx.core.runtime.VertxCoreRecorder$15.runWith(VertxCoreRecorder.java:637)
        at org.jboss.threads.EnhancedQueueExecutor$Task.doRunWith(EnhancedQueueExecutor.java:2675)
        at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2654)
        at org.jboss.threads.EnhancedQueueExecutor.runThreadBody(EnhancedQueueExecutor.java:1627)
        at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1594)
        at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:11)
        at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:11)
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.base/java.lang.Thread.run(Thread.java:1583)
Caused by: java.lang.NumberFormatException: For input string: "world"
        at java.base/java.lang.NumberFormatException.forInputString(NumberFormatException.java:67)
        at java.base/java.lang.Integer.parseInt(Integer.java:662)
        at java.base/java.lang.Integer.parseInt(Integer.java:778)
        at java.base/java.text.MessageFormat.makeFormat(MessageFormat.java:1483)
        ... 44 more

How to Reproduce?

Add following log message and run the code

Log.infof(new RuntimeException("Not important"), "Hello %s", "{world}");

Output of `uname -a` or `ver`

Linux REDACTED 5.14.0-547.el9.x86_64 #1 SMP PREEMPT_DYNAMIC Mon Dec 30 20:10:38 UTC 2024 x86_64 x86_64 x86_64 GNU/Linux

Output of `java -version`

OpenJDK 64-Bit Server VM Corretto-21.0.5.11.1 (build 21.0.5+11-LTS, mixed mode, sharing)

Quarkus version or git rev

3.17.5

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

Apache Maven 3.9.9 (8e8579a9e76f7d015ee5ec7bfcdc97d260186937)

Additional information

No response

The text was updated successfully, but these errors were encountered:

gastaldi · 2025-01-08T14:17:11Z

Fixed in 3.15.3. See #44540

gsmet · 2025-01-08T14:17:56Z

The OP is saying it's reproducible with 3.17.5 so it looks like we haven't fully fixed things.

gsmet · 2025-01-08T14:21:46Z

@Skrethel can you confirm you can only reproduce it in dev mode for 3.17.5?

I got it working with tests and prod mode but it's failing in dev mode for me.

gastaldi · 2025-01-08T14:22:39Z

Funny I can't reproduce with 999-SNAPSHOT, maybe something in main wasn't backported to 3.17?

gastaldi · 2025-01-08T14:23:48Z

Probably 3.17 is missing #44565

Skrethel · 2025-01-08T14:26:10Z

I've tested on 3.17.5 and it reproduces in dev mode.

Skrethel · 2025-01-08T14:28:56Z

I've used getting started with provided log message in one methods.

gastaldi · 2025-01-08T14:34:03Z

I can confirm that backporting 8fe3c76 to 3.17 solves the problem

Skrethel · 2025-01-08T14:34:25Z

Sorry I've missed the part about checking dev mode only.
It is not reproducing in compiled jar run from outside dev mode.

gsmet · 2025-01-08T14:37:56Z

Yeah, so I think the bug is in JBoss Log Manager even if the commit pointed by @gastaldi also fixes the issue:

https://github.com/jboss-logging/jboss-logmanager/blob/9482bdadfdceff48350a869dc3d24914ce367c12/src/main/java/org/jboss/logmanager/ExtHandler.java#L127-L137

When translating the message from printf to messageformat, we should escape the parameters or we can end up with a parameter injecting something that won't work with the new format.

In the case of the OP, when the translation occurs, we end up with hello {world}.

/cc @jamezp @dmlloyd

gsmet · 2025-01-08T14:38:56Z

The ship has sailed for 3.17.6 and 3.15.3 but we'll fix it in the next round.

gsmet · 2025-01-08T14:41:29Z

Thanks a lot for raising this with an easy way to reproduce it!

jamezp · 2025-01-08T18:41:30Z

@gsmet I actually think the problem more lies in

quarkus/core/deployment/src/main/java/io/quarkus/deployment/logging/LoggingResourceProcessor.java

Lines 440 to 445 in dbdfcea

    
           case MESSAGE_FORMAT -> { 
        
               Object[] p = elr.getParameters(); // can be null 
        
               Object[] np = p != null ? Arrays.copyOf(p, p.length + 1) : new Object[1]; 
        
               np[np.length - 1] = decoratedString; 
        
               elr.setParameters(np); 
        
               elr.setMessage(elr.getMessage() + "\n\n{" + (np.length - 1) + "}\n\n");

.

The LogRecord ends up getting wrapped and the message set to the formatted Hello {world} with null parameters. When the LoggingResourceProcess has a cause, it changes the format and adds parameters. In this case the message becomes:

Hello {world}\n\n{0}\n\n

And the LogRecord.setParameters() gets set to:

Exception in GreetingResource.java:15
	  13      @Produces(MediaType.TEXT_PLAIN)
	  14      public String hello() {
	→ 15          Log.infof(new RuntimeException("Test"), "Hello %s", "{world}");
	  16          return "Hello from Quarkus REST";
	  17      }

I'm not sure what the log manager can do about this. I think the LoggingResourceProcessor should potentially handle the escaping or format the current message, if applicable, and wrap in the LogRecord in an ExtLogRecord with a FormatSytle.PRINTF.

gsmet · 2025-01-08T19:15:47Z

@jamezp my debugging session showed the log record was changed prior to that in the code I pointed out in JBoss Log Manager.

gsmet · 2025-01-08T19:16:59Z

@jamezp if you want, we can do a quick call tomorrow? I'm in Europe/Paris timezone, we can sync on Zulip or Slack maybe?

gsmet · 2025-01-08T19:26:12Z

Note: the issue is with 3.17, you won't have the issue with main.

gsmet · 2025-01-08T19:47:25Z

We had a discussion with @jamezp and the issue is indeed in JBoss Log Manager: the oldRecord created in https://github.com/jboss-logging/jboss-logmanager/blob/9482bdadfdceff48350a869dc3d24914ce367c12/src/main/java/org/jboss/logmanager/ExtHandler.java#L127-L137 should be a NO_FORMAT record, not a MESSAGE_FORMAT record.

@jamezp is going to fix it.

We will backport the other commit from David though as it's better to avoid this code path anyway.

jamezp · 2025-01-08T20:14:01Z

For tracking purposes I've filed https://issues.redhat.com/browse/LOGMGR-356.

Skrethel added the kind/bug Something isn't working label Jan 8, 2025

quarkus-bot bot added the triage/needs-triage label Jan 8, 2025

gastaldi closed this as completed Jan 8, 2025

quarkus-bot bot removed the triage/needs-triage label Jan 8, 2025

gsmet reopened this Jan 8, 2025

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

FORMAT_FAILURE when using Log.errorf or Log.infof with throwable, message and string parameter containing { #45444

FORMAT_FAILURE when using Log.errorf or Log.infof with throwable, message and string parameter containing { #45444

Skrethel commented Jan 8, 2025

gastaldi commented Jan 8, 2025

gsmet commented Jan 8, 2025 •

edited

Loading

gsmet commented Jan 8, 2025

gastaldi commented Jan 8, 2025

gastaldi commented Jan 8, 2025

Skrethel commented Jan 8, 2025

Skrethel commented Jan 8, 2025

gastaldi commented Jan 8, 2025

Skrethel commented Jan 8, 2025

gsmet commented Jan 8, 2025 •

edited

Loading

gsmet commented Jan 8, 2025

gsmet commented Jan 8, 2025

jamezp commented Jan 8, 2025

gsmet commented Jan 8, 2025

gsmet commented Jan 8, 2025

gsmet commented Jan 8, 2025

gsmet commented Jan 8, 2025

jamezp commented Jan 8, 2025

FORMAT_FAILURE when using Log.errorf or Log.infof with throwable, message and string parameter containing { #45444

FORMAT_FAILURE when using Log.errorf or Log.infof with throwable, message and string parameter containing { #45444

Comments

Skrethel commented Jan 8, 2025

Describe the bug

Expected behavior

Actual behavior

How to Reproduce?

Output of uname -a or ver

Output of java -version

Quarkus version or git rev

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

Additional information

gastaldi commented Jan 8, 2025

gsmet commented Jan 8, 2025 • edited Loading

gsmet commented Jan 8, 2025

gastaldi commented Jan 8, 2025

gastaldi commented Jan 8, 2025

Skrethel commented Jan 8, 2025

Skrethel commented Jan 8, 2025

gastaldi commented Jan 8, 2025

Skrethel commented Jan 8, 2025

gsmet commented Jan 8, 2025 • edited Loading

gsmet commented Jan 8, 2025

gsmet commented Jan 8, 2025

jamezp commented Jan 8, 2025

gsmet commented Jan 8, 2025

gsmet commented Jan 8, 2025

gsmet commented Jan 8, 2025

gsmet commented Jan 8, 2025

jamezp commented Jan 8, 2025

Output of `uname -a` or `ver`

Output of `java -version`

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

gsmet commented Jan 8, 2025 •

edited

Loading

gsmet commented Jan 8, 2025 •

edited

Loading