search

quarkusio / quarkus

Quarkus: Supersonic Subatomic Java.
https://quarkus.io
Apache License 2.0
13.82k stars 2.69k forks source link

LogManager error of type FORMAT_FAILURE: Formatting error #35614

Closed plevart closed 1 year ago

plevart commented 1 year ago

Describe the bug

When starting a Quarkus 3.2.4 based app, the following is printed even before the Quarkus banner:

LogManager error of type FORMAT_FAILURE: Formatting error
java.lang.IllegalArgumentException: can't parse argument number: 
    at java.base/java.text.MessageFormat.makeFormat(MessageFormat.java:1454)
    at java.base/java.text.MessageFormat.applyPattern(MessageFormat.java:492)
    at java.base/java.text.MessageFormat.<init>(MessageFormat.java:371)
    at java.base/java.text.MessageFormat.format(MessageFormat.java:860)
    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.ExtHandler.publishToNestedHandlers(ExtHandler.java:97)
    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:269)
    at io.quarkus.deployment.steps.LoggingResourceProcessor$setupLoggingRuntimeInit1899082837.deploy_0(Unknown Source)
    at io.quarkus.deployment.steps.LoggingResourceProcessor$setupLoggingRuntimeInit1899082837.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:111)
    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)
    at io.quarkus.runner.GeneratedMain.main(Unknown Source)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:568)
    at io.quarkus.bootstrap.runner.QuarkusEntryPoint.doRun(QuarkusEntryPoint.java:61)
    at io.quarkus.bootstrap.runner.QuarkusEntryPoint.main(QuarkusEntryPoint.java:32)
Caused by: java.lang.NumberFormatException: For input string: ""
    at java.base/java.lang.NumberFormatException.forInputString(NumberFormatException.java:67)
    at java.base/java.lang.Integer.parseInt(Integer.java:678)
    at java.base/java.lang.Integer.parseInt(Integer.java:786)
    at java.base/java.text.MessageFormat.makeFormat(MessageFormat.java:1452)
    ... 31 more
__  ____  __  _____   ___  __ ____  ______ 
 --/ __ \/ / / / _ | / _ \/ //_/ / / / __/ 
 -/ /_/ / /_/ / __ |/ , _/ ,< / /_/ /\ \   
--\___\_\____/_/ |_/_/|_/_/|_|\____/___/   
17:55:21 WARN  <> [io.qu.op.ru.ex.ot.LateBoundBatchSpanProcessor] (main) No BatchSpanProcessor delegate specified, no action taken.
...normal app startup continues...

Debugging this reveals that the following message is passed to org.jboss.logmanager.ExtFormatter.formatMessage method:

VertxTracer delegate not set. Will not submit this trace. SpanKind: {}; Request: {}; Operation:{}.

...the logRecord passed to the method is an ExtLogRecord with formatStyle attribute being MESSAGE_FORMAT. Obviously indexes in the placeholders are missing for that formatStyle.

Expected behavior

No formatting exceptions in the early log.

Actual behavior

Like described

How to Reproduce?

Well, the opentelemetry extension is obviously a must, but I haven't established a recipy yet. It might even be a race since some services report this exception and some don't but are otherwise very similarly configured.

Output of uname -a or ver

openjdk version "17.0.7" 2023-04-18 LTS OpenJDK Runtime Environment (Red_Hat-17.0.7.0.7-1.el9_1) (build 17.0.7+7-LTS) OpenJDK 64-Bit Server VM (Red_Hat-17.0.7.0.7-1.el9_1) (build 17.0.7+7-LTS, mixed mode, sharing)

Output of java -version

openjdk version "17.0.7" 2023-04-18 LTS OpenJDK Runtime Environment (Red_Hat-17.0.7.0.7-1.el9_1) (build 17.0.7+7-LTS) OpenJDK 64-Bit Server VM (Red_Hat-17.0.7.0.7-1.el9_1) (build 17.0.7+7-LTS, mixed mode, sharing)

GraalVM version (if different from Java)

No response

Quarkus version or git rev

3.2.4

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

Apache Maven 3.9.4 (dfbb324ad4a7c8fb0bf182e6d91b0ae20e3d2dd9) Maven home: /home/peter/JavaApps/apache-maven-3 Java version: 17.0.8, vendor: Red Hat, Inc., runtime: /usr/lib/jvm/java-17-openjdk-17.0.8.0.7-1.fc38.x86_64 Default locale: en_US, platform encoding: UTF-8 OS name: "linux", version: "6.4.12-200.fc38.x86_64", arch: "amd64", family: "unix"

Additional information

No response

plevart commented 1 year ago

Another observation: two very similar services with similar configuration.

One that is NOT reporting the exception prints:

12:39:16 INFO <> [io.quarkus] (main) Installed features: [agroal, cdi, hibernate-envers, hibernate-orm, jdbc-mysql, jdbc-oracle, micrometer, narayana-jta, oidc, oidc-client, oidc-token-propagation-reactive, opentelemetry, rest-client-reactive, resteasy-reactive, resteasy-reactive-jackson, security, smallrye-context-propagation, smallrye-health, smallrye-openapi, vertx]

The other that IS reporting the exeption prints:

12:39:15 INFO <> [io.quarkus] (main) Installed features: [agroal, cdi, hibernate-envers, hibernate-orm, jdbc-mysql, jdbc-oracle, micrometer, narayana-jta, oidc, oidc-client, oidc-token-propagation-reactive, opentelemetry, rest-client-reactive, rest-client-reactive-jackson, resteasy-reactive, resteasy-reactive-jackson, security, smallrye-context-propagation, smallrye-health, smallrye-openapi, vertx]

The later one is using all extensions from the earlier one but is also adding the following extension: rest-client-reactive-jackson

I don't know whether this fact has anything to do with the exception. I'm merely trying to find differences.

geoand commented 1 year ago

Can you please attach a sample application that exhibits the problematic behavior?

Thanks

cescoffier commented 1 year ago

In general it's a %s that should be %d or the opposite.

plevart commented 1 year ago

It's neither %s nor %d in this instance. It's {} when it should be {1} or {2} or similar. It's the java.text.MessageFormat that throws exception. Or am I missing something?

jendib commented 1 year ago

I'm getting the same issue thrown by OpenTelemetryVertxTracingFactory which is also using {} instead of {0}. A quick search in Quarkus codebase shows more reference to {} that should probably be fixed as well.

geoand commented 1 year ago

We'll really need a sample application that behaves as described so we can debug

hellikopter commented 1 year ago

I need only the following pom.xml to recreate this issue.

<?xml version="1.0"?>
<project xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 https://maven.apache.org/xsd/maven-4.0.0.xsd"
         xmlns="http://maven.apache.org/POM/4.0.0"
         xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
    <modelVersion>4.0.0</modelVersion>
    <groupId>com.example</groupId>
    <artifactId>logmanager-error</artifactId>
    <version>1.0-SNAPSHOT</version>
    <properties>
        <compiler-plugin.version>3.11.0</compiler-plugin.version>
        <maven.compiler.release>17</maven.compiler.release>
        <project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
        <project.reporting.outputEncoding>UTF-8</project.reporting.outputEncoding>
        <quarkus.platform.artifact-id>quarkus-bom</quarkus.platform.artifact-id>
        <quarkus.platform.group-id>io.quarkus.platform</quarkus.platform.group-id>
        <quarkus.platform.version>3.3.1</quarkus.platform.version>
    </properties>
    <dependencyManagement>
        <dependencies>
            <dependency>
                <groupId>${quarkus.platform.group-id}</groupId>
                <artifactId>${quarkus.platform.artifact-id}</artifactId>
                <version>${quarkus.platform.version}</version>
                <type>pom</type>
                <scope>import</scope>
            </dependency>
        </dependencies>
    </dependencyManagement>
    <dependencies>
        <dependency>
            <groupId>io.quarkus</groupId>
            <artifactId>quarkus-opentelemetry</artifactId>
        </dependency>
        <dependency>
            <groupId>io.quarkus</groupId>
            <artifactId>quarkus-oidc</artifactId>
        </dependency>
    </dependencies>
    <build>
        <plugins>
            <plugin>
                <groupId>${quarkus.platform.group-id}</groupId>
                <artifactId>quarkus-maven-plugin</artifactId>
                <version>${quarkus.platform.version}</version>
                <extensions>true</extensions>
                <executions>
                    <execution>
                        <goals>
                            <goal>build</goal>
                            <goal>generate-code</goal>
                        </goals>
                    </execution>
                </executions>
            </plugin>
        </plugins>
    </build>
</project>
famod commented 1 year ago

+1 from me, Quarkus 3.3.1

PS: Sorry for not adding something substantial.

geoand commented 1 year ago

I could still not reproduce this.

It does looks similar to https://github.com/quarkusio/quarkus/pull/35638 however...

roman-svystun commented 1 year ago

@geoand This issue can be reproduced with a combination of quarkus-opentelemetry and quarkus-keycloak-authorization extensions. Here is a minimal app I could came up with:

mvn clean quarkus:dev

Listening for transport dt_socket at address: 5005
2023-09-05 09:51:24,307 INFO  [io.qua.oid.dep.dev.key.KeycloakDevServicesProcessor] (build-41) Dev Services for Keycloak started.
LogManager error of type FORMAT_FAILURE: Formatting error

java.lang.IllegalArgumentException: can't parse argument number: 
    at java.base/java.text.MessageFormat.makeFormat(MessageFormat.java:1454)
    at java.base/java.text.MessageFormat.applyPattern(MessageFormat.java:492)
    at java.base/java.text.MessageFormat.<init>(MessageFormat.java:371)
    at java.base/java.text.MessageFormat.format(MessageFormat.java:860)
    at org.jboss.logmanager.ExtFormatter.formatMessageLegacy(ExtFormatter.java:107)
    at org.jboss.logmanager.ExtFormatter.formatMessage(ExtFormatter.java:70)
    at org.jboss.logmanager.formatters.ColorPatternFormatter.formatMessage(ColorPatternFormatter.java:139)
    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.ColorPatternFormatter$ColorStep.render(ColorPatternFormatter.java:160)
    at org.jboss.logmanager.formatters.MultistepFormatter.format(MultistepFormatter.java:86)
    at io.quarkus.runtime.logging.BannerFormatter.format(BannerFormatter.java:54)
    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 io.quarkus.deployment.logging.LoggingResourceProcessor$2.accept(LoggingResourceProcessor.java:413)
    at io.quarkus.deployment.logging.LoggingResourceProcessor$2.accept(LoggingResourceProcessor.java:389)
    at io.quarkus.runtime.logging.LoggingSetupRecorder$7.publish(LoggingSetupRecorder.java:592)
    at org.jboss.logmanager.ExtHandler.publishToNestedHandlers(ExtHandler.java:97)
    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:269)
    at io.quarkus.deployment.steps.LoggingResourceProcessor$setupLoggingRuntimeInit1899082837.deploy_0(Unknown Source)
    at io.quarkus.deployment.steps.LoggingResourceProcessor$setupLoggingRuntimeInit1899082837.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:111)
    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)
    at io.quarkus.runner.GeneratedMain.main(Unknown Source)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:568)
    at io.quarkus.runner.bootstrap.StartupActionImpl$1.run(StartupActionImpl.java:104)
    at java.base/java.lang.Thread.run(Thread.java:833)
Caused by: java.lang.NumberFormatException: For input string: ""
    at java.base/java.lang.NumberFormatException.forInputString(NumberFormatException.java:67)
    at java.base/java.lang.Integer.parseInt(Integer.java:678)
    at java.base/java.lang.Integer.parseInt(Integer.java:786)
    at java.base/java.text.MessageFormat.makeFormat(MessageFormat.java:1452)
    ... 36 more
java.util.logging.ErrorManager: 1: Nested handler publication threw an exception
java.lang.IllegalArgumentException: can't parse argument number: 
    at java.base/java.text.MessageFormat.makeFormat(MessageFormat.java:1454)
    at java.base/java.text.MessageFormat.applyPattern(MessageFormat.java:492)
    at java.base/java.text.MessageFormat.<init>(MessageFormat.java:371)
    at java.base/java.text.MessageFormat.format(MessageFormat.java:860)
    at org.jboss.logmanager.ExtFormatter.formatMessageLegacy(ExtFormatter.java:107)
    at org.jboss.logmanager.ExtFormatter.formatMessage(ExtFormatter.java:70)
    at io.quarkus.devui.runtime.logstream.JsonFormatter.toJsonObject(JsonFormatter.java:27)
    at io.quarkus.devui.runtime.logstream.MutinyLogHandler.doPublish(MutinyLogHandler.java:30)
    at org.jboss.logmanager.ExtHandler.publish(ExtHandler.java:66)
    at org.jboss.logmanager.ExtHandler.publishToNestedHandlers(ExtHandler.java:97)
    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:269)
    at io.quarkus.deployment.steps.LoggingResourceProcessor$setupLoggingRuntimeInit1899082837.deploy_0(Unknown Source)
    at io.quarkus.deployment.steps.LoggingResourceProcessor$setupLoggingRuntimeInit1899082837.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:111)
    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)
    at io.quarkus.runner.GeneratedMain.main(Unknown Source)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:568)
    at io.quarkus.runner.bootstrap.StartupActionImpl$1.run(StartupActionImpl.java:104)
    at java.base/java.lang.Thread.run(Thread.java:833)
Caused by: java.lang.NumberFormatException: For input string: ""
    at java.base/java.lang.NumberFormatException.forInputString(NumberFormatException.java:67)
    at java.base/java.lang.Integer.parseInt(Integer.java:678)
    at java.base/java.lang.Integer.parseInt(Integer.java:786)
    at java.base/java.text.MessageFormat.makeFormat(MessageFormat.java:1452)
    ... 27 more
__  ____  __  _____   ___  __ ____  ______ 
 --/ __ \/ / / / _ | / _ \/ //_/ / / / __/ 
 -/ /_/ / /_/ / __ |/ , _/ ,< / /_/ /\ \   
--\___\_\____/_/ |_/_/|_/_/|_|\____/___/   
2023-09-05 09:51:25,202 INFO  [org.acm.rep.GreetingApplicationLifeCycle] (Quarkus Main Thread) --------------------------- quarkus-greeting-service ---------------------------

2023-09-05 09:51:25,203 INFO  [org.acm.rep.GreetingApplicationLifeCycle] (Quarkus Main Thread) -------------------------------------------------------------------------------
2023-09-05 09:51:25,203 INFO  [org.acm.rep.GreetingApplicationLifeCycle] (Quarkus Main Thread) -------------------------------------------------------------------------------
2023-09-05 09:51:25,204 INFO  [org.acm.rep.GreetingApplicationLifeCycle] (Quarkus Main Thread) -------------------------------------------------------------Powered by Quarkus
geoand commented 1 year ago

Thanks a lot @roman-svystun

geoand commented 1 year ago

@dmlloyd @jamezp I don't see how org.jboss.logmanager.ExtFormatter supports the 

log.infov("here {}", somevariable)

type of logging - which is essentially what this issue is about.

Can you point me in the right direction?

Thanks

geoand commented 1 year ago

To be clear, it would be easy to overcome the issue mentioned here by simply not using that logging pattern in Quarkus code, but I would first really like to understand why it doesn't work, hence my question above.

dmlloyd commented 1 year ago

Which library is logging in this way? I saw the message that's failing but not the library which is doing it.

To answer your question directly, the numeral-less {} is not supported by JUL either. It's an extension used by some other logging library. So, what we need to do is identify what library it is, what logging API they're actually talking to, and what logging API they intended to talk to. From there we'll determine whether it's appropriate to enhance JBoss LogManager (and JBoss Logging) to support this non-standard form based on the rules of whatever logging library they use outside of Quarkus.

geoand commented 1 year ago

Which library is logging in this way? I saw the message that's failing but not the library which is doing it.

Quarkus source code :)

Apparently some folks (it looks like I am included in those people) thought it would work.

dmlloyd commented 1 year ago

Then I think it's a simple bug. This format style isn't supported. Quarkus source code should generally always just use the printf-style formatting strategy.

geoand commented 1 year ago

Gotcha, that's exactly what I wanted to know, thanks

geoand commented 1 year ago

https://github.com/quarkusio/quarkus/pull/35740 takes care of it

plevart commented 1 year ago

Thanks for quick fix! Could this be included in 3.3.2 ? Just a wish. It's not very important though. The app continues to run despite this.

geoand commented 1 year ago

It will be backported, yes

gsmet commented 1 year ago

It will be backported but not in 3.3.2 as this ship has sailed yesterday.

geoand commented 1 year ago

Ah okay, 3.3.3 it is then (if that comes to be)

pdolezal commented 1 year ago

Btw. it is just nitpicking, but the message to be logged uses pattern "SpanKind: {0}; Request: {1}; Operation:{2}." and I suppose that a space should be between Operation: and the argument (as it is everywhere else).

geoand commented 1 year ago

Sounds like a great opportunity for a contribution 😉