Quarkus: LogManager FORMAT_FAILURE on application startup

Created on 9 Oct 2020 · 12Comments · Source: quarkusio/quarkus

Describe the bug

Relates to https://github.com/apache/camel-quarkus/issues/1891.

Since upgrading to Quarkus 1.9.0.CR1, I noticed errors on some of the camel-quarkus integration tests. It seems to be related to logging. In our camel-jira integration test, there's a point where Camel is trying to log the name & value of a configuration property. It results in:

2020-10-08T08:32:32.2091764Z LogManager error of type FORMAT_FAILURE: Formatting error
2020-10-08T08:32:32.2099488Z java.lang.IllegalArgumentException: can't parse argument number: {env:JIRA_PASSWORD:s3cr3t}
2020-10-08T08:32:32.2106490Z    at java.base/java.text.MessageFormat.makeFormat(MessageFormat.java:1451)
2020-10-08T08:32:32.2135815Z    at java.base/java.text.MessageFormat.applyPattern(MessageFormat.java:491)
2020-10-08T08:32:32.2137278Z    at java.base/java.text.MessageFormat.<init>(MessageFormat.java:370)
2020-10-08T08:32:32.2138476Z    at java.base/java.text.MessageFormat.format(MessageFormat.java:859)
2020-10-08T08:32:32.2140257Z    at org.jboss.logmanager.ExtFormatter.formatMessageLegacy(ExtFormatter.java:107)
2020-10-08T08:32:32.2142371Z    at org.jboss.logmanager.ExtFormatter.formatMessage(ExtFormatter.java:70)
2020-10-08T08:32:32.2146855Z    at org.jboss.logmanager.formatters.Formatters$16.renderRaw(Formatters.java:781)
2020-10-08T08:32:32.2148459Z    at org.jboss.logmanager.formatters.Formatters$JustifyingFormatStep.render(Formatters.java:221)
2020-10-08T08:32:32.2150571Z    at org.jboss.logmanager.formatters.MultistepFormatter.format(MultistepFormatter.java:86)
2020-10-08T08:32:32.2156574Z    at org.jboss.logmanager.ExtFormatter.format(ExtFormatter.java:32)
2020-10-08T08:32:32.2160057Z    at org.jboss.logmanager.handlers.WriterHandler.doPublish(WriterHandler.java:43)
2020-10-08T08:32:32.2161768Z    at org.jboss.logmanager.ExtHandler.publish(ExtHandler.java:66)
2020-10-08T08:32:32.2163405Z    at org.jboss.logmanager.handlers.DelayedHandler.publishToChildren(DelayedHandler.java:208)
2020-10-08T08:32:32.2166475Z    at org.jboss.logmanager.handlers.DelayedHandler.doPublish(DelayedHandler.java:49)
2020-10-08T08:32:32.2174299Z    at org.jboss.logmanager.ExtHandler.publish(ExtHandler.java:66)
2020-10-08T08:32:32.2179223Z    at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:316)
2020-10-08T08:32:32.2182231Z    at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:324)
2020-10-08T08:32:32.2193551Z    at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:324)
2020-10-08T08:32:32.2194754Z    at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:324)
2020-10-08T08:32:32.2196247Z    at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:324)
2020-10-08T08:32:32.2197233Z    at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:324)
2020-10-08T08:32:32.2206325Z    at org.jboss.logmanager.Logger.logRaw(Logger.java:748)
2020-10-08T08:32:32.2207408Z    at org.jboss.logmanager.Logger.log(Logger.java:706)
2020-10-08T08:32:32.2208843Z    at org.jboss.logging.JBossLogManagerLogger.doLog(JBossLogManagerLogger.java:44)

The source of the config value is here. It looks like the '{' & '}' characters are possibly causing the problem.

I wonder if the slf4j-jboss-logging upgrade to 1.2.1.Final is the problem? If force a downgrade back to 1.2.0.Final, the problem does not occur.

I did a quick scan of the Quarkus CI build log and noticed a similar exception being thrown in SentryLoggerDisabledTest.

The tests still pass ok, there's just the ugly stack trace when the app starts up.

Expected behavior
The desired log message should be printed without errors.

Actual behavior
Logging fails with FORMAT_FAILURE.

To Reproduce

Clone the camel-quarkus project
Build (quickly): mvn clean install -DskipTests -Dquarkus.build.skip -Denforce=false -T1C
Run integration tests

To replicate the error in the linked issue:

mvn clean test -pl :camel-quarkus-integration-test-jira

Same error cause but different stack trace (Note: You'll need Docker running for this one):

mvn clean test -pl :camel-quarkus-integration-test-activemq

kinbug

Source

jamesnetherton

All 12 comments

I wonder if it could be related to https://github.com/jboss-logging/slf4j-jboss-logging/commit/1204d4301b82aeddfb0b0b3c0905f48df9c266d7 .

I will downgrade in the meantime.

/cc @jamezp

gsmet on 9 Oct 2020

👍1

We experience the same problem, but with 1.8.2.Final.
The problem occurs, if a parameter in the log statement prints out JSON in the toString().
In our case, we have some Avro objects, where these object prints out it JSON serialization on the toString method.
We use SLF4J for logging. We do something like:

SomeAvroObject myAvroObject = ....;
logger.info("Here is a log entry for my object={}", myAvroObject);

For my understanding, toString() on myAvroObject should be called, which returns JSON.
Then some strange things happen, the the LogManager seem to interpret this JSON?!
We get this stack trace:

java.lang.IllegalArgumentException: can't parse argument number: "m2mDeviceId": "313331000000045"
    at java.text.MessageFormat.makeFormat(MessageFormat.java:1429)
    at java.text.MessageFormat.applyPattern(MessageFormat.java:479)
    at java.text.MessageFormat.<init>(MessageFormat.java:362)
    at java.text.MessageFormat.format(MessageFormat.java:840)
    at org.jboss.logmanager.ExtFormatter.formatMessageLegacy(ExtFormatter.java:107)
    at org.jboss.logmanager.ExtFormatter.formatMessage(ExtFormatter.java:70)
    at org.jboss.logmanager.formatters.Formatters$16.renderRaw(Formatters.java:781)
    at org.jboss.logmanager.formatters.Formatters$JustifyingFormatStep.render(Formatters.java:221)
    at org.jboss.logmanager.formatters.MultistepFormatter.format(MultistepFormatter.java:86)
    at io.quarkus.runtime.logging.BannerFormatter.format(BannerFormatter.java:56)
    at org.jboss.logmanager.ExtFormatter.format(ExtFormatter.java:32)
    at org.jboss.logmanager.handlers.WriterHandler.doPublish(WriterHandler.java:43)
    at org.jboss.logmanager.ExtHandler.publish(ExtHandler.java:66)
    at org.jboss.logmanager.handlers.DelayedHandler.publishToChildren(DelayedHandler.java:208)
    at org.jboss.logmanager.handlers.DelayedHandler.doPublish(DelayedHandler.java:49)
    at org.jboss.logmanager.ExtHandler.publish(ExtHandler.java:66)
    at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:316)
    at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:324)
    at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:324)
    at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:324)
    at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:324)
    at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:324)
    at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:324)
    at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:324)
    at org.jboss.logmanager.Logger.logRaw(Logger.java:748)
    at org.jboss.logmanager.Logger.log(Logger.java:706)
    at org.jboss.logging.JBossLogManagerLogger.doLog(JBossLogManagerLogger.java:44)
    at org.jboss.logging.Logger.log(Logger.java:2103)
    at org.jboss.slf4j.JBossLoggerAdapter.log(JBossLoggerAdapter.java:302)
    at org.jboss.slf4j.JBossLoggerAdapter.info(JBossLoggerAdapter.java:196)
    ...

Where m2mDeviceId is the first field of the resulting JSON.

I have tested this with 1.5.2, 1.60, 1.7.1, 1.8.0 and 1.8.1 and it works fine.
Upgrade to 1.8.2 causes this issue.

skasten on 9 Oct 2020

@skasten I suspect downgrading slf4j-jboss-logging to 1.2.0.Final will fix your issue. It was upgraded in 1.8.2.Final.

gsmet on 9 Oct 2020

@gsmet Yes, with 1.2.0.Final it works.

skasten on 9 Oct 2020

/cc @dmlloyd too

Interesting comment is there: https://github.com/quarkusio/quarkus/issues/12615#issuecomment-706024360 .

gsmet on 9 Oct 2020

I just pushed 1.8.3.Final with the downgrade.

gsmet on 9 Oct 2020

The reason main reason is this is caused by having abstractions over abstractions :) Since slf4j-jboss-logging is being used it delegates slf4j to jboss-logging which in turn delegates to jboss-logmanager. jboss-logging passes the format parameters to jboss-logmanager and it attempts to format an already formatted message. We pass the parameters though so they end up in the structured formatters like the JSON formatter output.

If there is a slf4j-jboss-logmanager project which would delegate directly to jboss-logmanager. However it would need a minor update now that I look at it. There could be a reason that I don't recall that slf4j-jboss-logging is being used.

jamezp on 9 Oct 2020

👍1

I created https://github.com/jboss-logging/slf4j-jboss-logging/issues/15 .

gsmet on 13 Oct 2020

@gsmet I think the proper solution will be to switch to using https://github.com/jboss-logging/slf4j-jboss-logmanager/. I made some updates yesterday and can cut a release if it's something you want for Quarkus.

jamezp on 13 Oct 2020

@gsmet @jamezp I am looking at, a solution on switching to https://github.com/jboss-logging/slf4j-jboss-logmanager/, as sugested by @jamezp. I think i have something working local, there is a changed required to the slf4j-jboss-logmanager, and updating the required dependencies in quarkus.
The changes in version 1.2.1.Final of slf4j-jboss-logging, should be rollback.