Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

LogManager error of type FORMAT_FAILURE: Formatting error #35614

Closed
plevart opened this issue Aug 29, 2023 · 24 comments · Fixed by #35740
Closed

LogManager error of type FORMAT_FAILURE: Formatting error #35614

plevart opened this issue Aug 29, 2023 · 24 comments · Fixed by #35740
Labels
area/logging kind/bug Something isn't working
Milestone

Comments

@plevart
Copy link
Contributor

plevart commented Aug 29, 2023

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 plevart added the kind/bug Something isn't working label Aug 29, 2023
@plevart
Copy link
Contributor Author

plevart commented Aug 29, 2023

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
Copy link
Contributor

geoand commented Aug 29, 2023

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

Thanks

@geoand geoand added triage/needs-reproducer We are waiting for a reproducer. area/logging labels Aug 29, 2023
@cescoffier
Copy link
Member

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

@plevart
Copy link
Contributor Author

plevart commented Sep 1, 2023

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
Copy link

jendib commented Sep 2, 2023

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
Copy link
Contributor

geoand commented Sep 2, 2023

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

@hellikopter
Copy link

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
Copy link
Member

famod commented Sep 4, 2023

+1 from me, Quarkus 3.3.1

PS: Sorry for not adding something substantial.

@geoand
Copy link
Contributor

geoand commented Sep 5, 2023

I could still not reproduce this.

It does looks similar to #35638 however...

@roman-svystun
Copy link

@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
Copy link
Contributor

geoand commented Sep 5, 2023

Thanks a lot @roman-svystun

@geoand
Copy link
Contributor

geoand commented Sep 5, 2023

@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
Copy link
Contributor

geoand commented Sep 5, 2023

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.

@geoand geoand removed the triage/needs-reproducer We are waiting for a reproducer. label Sep 5, 2023
@dmlloyd
Copy link
Member

dmlloyd commented Sep 5, 2023

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
Copy link
Contributor

geoand commented Sep 5, 2023

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
Copy link
Member

dmlloyd commented Sep 5, 2023

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
Copy link
Contributor

geoand commented Sep 5, 2023

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

geoand added a commit to geoand/quarkus that referenced this issue Sep 5, 2023
@geoand
Copy link
Contributor

geoand commented Sep 5, 2023

#35740 takes care of it

famod added a commit that referenced this issue Sep 5, 2023
Fix invalid logging pattern
@quarkus-bot quarkus-bot bot added this to the 3.4 - main milestone Sep 5, 2023
@plevart
Copy link
Contributor Author

plevart commented Sep 6, 2023

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
Copy link
Contributor

geoand commented Sep 6, 2023

It will be backported, yes

@gsmet
Copy link
Member

gsmet commented Sep 6, 2023

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

@geoand
Copy link
Contributor

geoand commented Sep 6, 2023

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

@pdolezal
Copy link

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
Copy link
Contributor

geoand commented Sep 14, 2023

Sounds like a great opportunity for a contribution 😉

@aloubyansky aloubyansky modified the milestones: 3.4.0.CR1, 3.2.8.Final Oct 25, 2023
aloubyansky pushed a commit to aloubyansky/quarkus that referenced this issue Oct 25, 2023
Closes: quarkusio#35614
(cherry picked from commit f2a2516)
holly-cummins pushed a commit to holly-cummins/quarkus that referenced this issue Feb 8, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area/logging kind/bug Something isn't working
Projects
None yet
Development

Successfully merging a pull request may close this issue.