Log format is ignored in uber-jar if there is a custom main method

[cdhermann]

Describe the bug

Console log format is set to %d{yyyy-MM-dd HH:mm:ss} %-5p [%c] %s%e%n in
application.properties but the log output on the console looks like this:

cdh:~/uber-jar-demo$ java -jar target/uber-jar-demo-1.0.0-SNAPSHOT-runner.jar
Feb 03, 2022 5:56:23 AM org.acme.Main main
INFO: Main method
Feb 03, 2022 5:56:23 AM org.jboss.threads.Version <clinit>
INFO: JBoss Threads version 3.4.2.Final
Feb 03, 2022 5:56:23 AM io.quarkus.bootstrap.runner.Timing printStartupTime
INFO: uber-jar-demo 1.0.0-SNAPSHOT on JVM (powered by Quarkus 2.6.3.Final) started in 0.438s. 
Feb 03, 2022 5:56:23 AM io.quarkus.bootstrap.runner.Timing printStartupTime
INFO: Profile prod activated. 
Feb 03, 2022 5:56:23 AM io.quarkus.bootstrap.runner.Timing printStartupTime
INFO: Installed features: [cdi, picocli]
Feb 03, 2022 5:56:23 AM org.acme.HelloCommand run
INFO: Saying 'World'
Feb 03, 2022 5:56:23 AM io.quarkus.bootstrap.runner.Timing printStopTime
INFO: uber-jar-demo stopped in 0.030s
__  ____  __  _____   ___  __ ____  ______ 
 --/ __ \/ / / / _ | / _ \/ //_/ / / / __/ 
 -/ /_/ / /_/ / __ |/ , _/ ,< / /_/ /\ \   
--\___\_\____/_/ |_/_/|_/_/|_|\____/___/

Packaging a fast-jar and running the application does all the pretty-printing:

__  ____  __  _____   ___  __ ____  ______ 
 --/ __ \/ / / / _ | / _ \/ //_/ / / / __/ 
 -/ /_/ / /_/ / __ |/ , _/ ,< / /_/ /\ \   
--\___\_\____/_/ |_/_/|_/_/|_|\____/___/   
2022-02-03 06:00:56 INFO  [staticLogger] Main method
2022-02-03 06:00:56 INFO  [io.quarkus] uber-jar-demo 1.0.0-SNAPSHOT on JVM (powered by Quarkus 2.6.3.Final) started in 0.517s. 
2022-02-03 06:00:56 INFO  [io.quarkus] Profile prod activated. 
2022-02-03 06:00:56 INFO  [io.quarkus] Installed features: [cdi, picocli]
2022-02-03 06:00:57 INFO  [inCommand] Saying 'World'
2022-02-03 06:00:57 INFO  [io.quarkus] uber-jar-demo stopped in 0.031s

This seems to happen only if there is a custom main method.

The behavior is the same on Linux, Mac and Windows.

Expected behavior

Log formatting is the same no matter which package type is used.

Actual behavior

Packaging a uber-jar ignories the log formatting whereas fast-jar for example obeys the log formatting configuration.

If there is no custom main method but package types behave the same.

How to Reproduce?

1. Checkout the demo project at https://github.com/itbh-at/uber-jar-demo
2. Build with -Dquarkus.package.type=uber-jar and run the application
3. Build with -Dquarkus.package.type=fast-jarand run the application
4. Compare the outputs

Output of uname -a or ver

Darwin cdh.localdomain 21.2.0 Darwin Kernel Version 21.2.0: Sun Nov 28 20:29:10 PST 2021; root:xnu-8019.61.5~1/RELEASE_ARM64_T8101 arm64

Output of java -version

java version "17" 2021-09-14 LTS Java(TM) SE Runtime Environment (build 17+35-LTS-2724) Java HotSpot(TM) 64-Bit Server VM (build 17+35-LTS-2724, mixed mode, sharing)

GraalVM version (if different from Java)

No response

Quarkus version or git rev

2.7.0.Final (also testet with 2.6.3.Final)

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

maven

Additional information

No response

[PVergneau]

Hi there.

I suffered the same issue for too long on a Quarkus + Kotlin app , although there was no custom main, nor agent, not anything (and just only a basic hello resource on a minimalist project i played with). It appears there is a kind "explanation" in #2152

The workaround is to add
-Djava.util.logging.manager=org.jboss.logmanager.LogManager
at runtime when you execute your uberjar. I tried with your project and it worked.

Pascal.

[faermanj]

Similar issue here. I do have a custom main, and deppending on how it is launched logging is different.
In dev mode logging configuration works fine, but when running with java -jar, i always get the quarkus init logging

Oct 30, 2022 10:56:57 AM io.quarkus.bootstrap.runner.Timing printStartupTime
INFO: cloud-janitor 1.2.0 on JVM (powered by Quarkus 2.13.3.Final) started in 0.435s. 
Oct 30, 2022 10:56:57 AM io.quarkus.bootstrap.runner.Timing printStartupTime
INFO: Profile prod activated. 
Oct 30, 2022 10:56:57 AM io.quarkus.bootstrap.runner.Timing printStartupTime
INFO: Installed features: [cdi, config-yaml, qute]

I wish that did not show up, perhaps at least reduce the priority of these messages so we can limit console to INFO and get rid of them?

[gsmet]

So from what I can see, you get the problem if you use a static logger in the Main class. That is because the java.util.logging.manager defined in Quarkus.run is actually called too late in this case.

One possibility could be to have something similar to QuarkusEntryPoint we use for fast-jar for uber-jars too, but a much simpler version that would just define the system properties and then run the actual main.

I can have a look at doing that but I would prefer to have @stuartwdouglas and @geoand 's opinion first.

[geoand]

We actually do set System.setProperty("java.util.logging.manager", "org.jboss.logmanager.LogManager"); in the generated io.quarkus.runner.ApplicationImpl, so doing it in some place that makes sense for this case is probably fine.

[mieber]

So from what I can see, you get the problem if you use a static logger in the Main class. That is because the java.util.logging.manager defined in Quarkus.run is actually called too late in this case.

One possibility could be to have something similar to QuarkusEntryPoint we use for fast-jar for uber-jars too, but a much simpler version that would just define the system properties and then run the actual main.

I can have a look at doing that but I would prefer to have @stuartwdouglas and @geoand 's opinion first.

Understanding that helped me for our current application. I now do this in my main class:

static {
    System.setProperty("java.util.logging.manager", "org.jboss.logmanager.LogManager");
    LOG = Logger.getLogger(MyApp.class.getName());
}

Instead of just the static creation.

[geoand]

Let's close this as won't fix as there is a simple workaround and from the looks of it, the problem only occurs in rare cases