LogManager FORMAT_FAILURE on application startup #12615

jamesnetherton · 2020-10-09T06:57:09Z

Describe the bug

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

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

gsmet · 2020-10-09T07:38:46Z

I wonder if it could be related to jboss-logging/slf4j-jboss-logging@1204d43 .

I will downgrade in the meantime.

/cc @jamezp

Fixes quarkusio#12615

skasten · 2020-10-09T07:55:38Z

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.

gsmet · 2020-10-09T07:58:57Z

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

skasten · 2020-10-09T08:01:56Z

@gsmet Yes, with 1.2.0.Final it works.

gsmet · 2020-10-09T08:16:07Z

/cc @dmlloyd too

Interesting comment is there: #12615 (comment) .

Fixes quarkusio#12615

gsmet · 2020-10-09T15:06:08Z

I just pushed 1.8.3.Final with the downgrade.

jamezp · 2020-10-09T15:40:50Z

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.

Fixes quarkusio#12615

gsmet · 2020-10-13T16:03:42Z

I created jboss-logging/slf4j-jboss-logging#15 .

jamezp · 2020-10-13T16:49:50Z

@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.

SlyngDK · 2020-10-13T17:51:50Z

@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.

SlyngDK · 2020-10-13T18:17:57Z

@jamezp I have created jboss-logging/slf4j-jboss-logmanager#10, to fix the issue I have seen.

SlyngDK · 2020-10-13T19:39:47Z

#12659 have solve the issue.
I have created a draft PR #12692 on the change of the slf4j implementation.
Test run local looks promising, I will look at the CI results tomorrow.

jamesnetherton added the kind/bug Something isn't working label Oct 9, 2020

gsmet added a commit to gsmet/quarkus that referenced this issue Oct 9, 2020

Downgrade slf4j-jboss-logging to 1.2.0.Final

5c6ea77

Fixes quarkusio#12615

gsmet mentioned this issue Oct 9, 2020

Downgrade slf4j-jboss-logging to 1.2.0.Final #12619

Merged

gsmet added a commit to gsmet/quarkus that referenced this issue Oct 9, 2020

Downgrade slf4j-jboss-logging to 1.2.0.Final

62528fb

Fixes quarkusio#12615

gsmet closed this as completed in #12619 Oct 9, 2020

gsmet added this to the 1.10 - master milestone Oct 9, 2020

gsmet mentioned this issue Oct 9, 2020

Logging an argument with a '{' leads to FORMAT_FAILURE #12634

Closed

gsmet modified the milestones: 1.10 - master, 1.9.0.Final Oct 10, 2020

gsmet added a commit to gsmet/quarkus that referenced this issue Oct 10, 2020

Downgrade slf4j-jboss-logging to 1.2.0.Final

a114827

Fixes quarkusio#12615

SlyngDK mentioned this issue Oct 10, 2020

Added forwarding of parameters. jboss-logging/slf4j-jboss-logging#10

Merged

gsmet mentioned this issue Oct 13, 2020

Major issue with latest 1.2.1.Final jboss-logging/slf4j-jboss-logging#15

Closed

SlyngDK mentioned this issue Oct 13, 2020

Changed the usage from slf4j-jboss-logging to slf4j-jboss-logmanager. #12692

Merged

gsmet modified the milestones: 1.9.0.Final, 1.8.3.Final Oct 19, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

LogManager FORMAT_FAILURE on application startup #12615

LogManager FORMAT_FAILURE on application startup #12615

jamesnetherton commented Oct 9, 2020

gsmet commented Oct 9, 2020

skasten commented Oct 9, 2020

gsmet commented Oct 9, 2020

skasten commented Oct 9, 2020

gsmet commented Oct 9, 2020

gsmet commented Oct 9, 2020

jamezp commented Oct 9, 2020

gsmet commented Oct 13, 2020

jamezp commented Oct 13, 2020

SlyngDK commented Oct 13, 2020

SlyngDK commented Oct 13, 2020

SlyngDK commented Oct 13, 2020

LogManager FORMAT_FAILURE on application startup #12615

LogManager FORMAT_FAILURE on application startup #12615

Comments

jamesnetherton commented Oct 9, 2020

gsmet commented Oct 9, 2020

skasten commented Oct 9, 2020

gsmet commented Oct 9, 2020

skasten commented Oct 9, 2020

gsmet commented Oct 9, 2020

gsmet commented Oct 9, 2020

jamezp commented Oct 9, 2020

gsmet commented Oct 13, 2020

jamezp commented Oct 13, 2020

SlyngDK commented Oct 13, 2020

SlyngDK commented Oct 13, 2020

SlyngDK commented Oct 13, 2020