Hi,

1) I simply create a java native image project by the template from start.spring.io for native image base on spring boot 3.0, and the sample code is in git. 2) build the native image using "mvn spring-boot:build-image -Dmaven.test.skip=true" 3) run the image in local docker enviroment, strange log output as below

   .   ____          _            __ _ _
  /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
 ( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
  \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
   '  |____| .__|_| |_|_| |_\__, | / / / /
  =========|_|==============|___/=/_/_/_/
  :: Spring Boot ::            (v3.0.0-RC1)

%PARSER_ERROR[d] %PARSER_ERROR[p] 1 --- [%PARSER_ERROR[t]] %PARSER_ERROR[logger] : %PARSER_ERROR[m]%PARSER_ERROR[n]
%PARSER_ERROR[d] %PARSER_ERROR[p] 1 --- [%PARSER_ERROR[t]] %PARSER_ERROR[logger] : %PARSER_ERROR[m]%PARSER_ERROR[n]
%PARSER_ERROR[d] %PARSER_ERROR[p] 1 --- [%PARSER_ERROR[t]] %PARSER_ERROR[logger] : %PARSER_ERROR[m]%PARSER_ERROR[n]
 ```

4) deploy it to K8S, no log is output just below

. _ _ __ _ _ /\ / ' __ _ () __ __ _ \ \ \ \ ( ( )_ | ' | '| | ' \/ _` | \ \ \ \ \/ )| |)| | | | | || (| | ) ) ) ) ' |_| .|| ||| |_, | / / / / =========|_|==============|/=//// :: Spring Boot :: (v3.0.0-RC1)


5) For non-native image, the log is printed as

2022-11-02 15:16:29,866 INFO org.springframework.boot.StartupInfoLogger [main] Starting TestLogApplication using Java 17.0.4.1 on zhiyong-hp with PID 27892 (C:\projects\test-log\target\classes started by zhiyongli in C:\projects\test-log) 2022-11-02 15:16:29,870 INFO org.springframework.boot.SpringApplication [main] No active profile set, falling back to 1 default profile: "default" 2022-11-02 15:16:30,328 INFO org.springframework.boot.StartupInfoLogger [main] Started TestLogApplication in 0.905 seconds (process running for 1.602)

Process finished with exit code 0 ```

Comment From: wilkinsona

Thanks for trying RC1 and for the sample. Unfortunately, I cannot reproduce the behaviour that you have described using the sample. When I launch the Docker container, I see the following output:

$ docker run docker.io/showpune/test-log:0.0.1-SNAPSHOT

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::            (v3.0.0-RC1)

2022-11-02T09:58:31.726Z  INFO 1 --- [           main] com.example.testlog.TestLogApplication   : Starting AOT-processed TestLogApplication using Java 17.0.5 on 63e260664e1a with PID 1 (/workspace/com.example.testlog.TestLogApplication started by cnb in /workspace)
2022-11-02T09:58:31.726Z  INFO 1 --- [           main] com.example.testlog.TestLogApplication   : No active profile set, falling back to 1 default profile: "default"
2022-11-02T09:58:31.730Z  INFO 1 --- [           main] com.example.testlog.TestLogApplication   : Started TestLogApplication in 0.011 seconds (process running for 0.018)

This is Spring Boot's default logging configuration. The default configuration is being used due to https://github.com/spring-projects/spring-boot/issues/32841. This bug prevents the application from finding the AOT-processed logging configuration so it falls back to using the default configuration.

If I switch to 3.0.0-SNAPSHOT (available from https://repo.spring.io/snapshot), your custom logging configuration is used:

$ docker run docker.io/showpune/test-log:0.0.1-SNAPSHOT

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::       (v3.0.0-SNAPSHOT)

2022-11-02 10:10:59,886 INFO org.springframework.boot.StartupInfoLogger [main] Starting AOT-processed TestLogApplication using Java 17.0.5 with PID 1 (/workspace/com.example.testlog.TestLogApplication started by cnb in /workspace)
2022-11-02 10:10:59,886 INFO org.springframework.boot.SpringApplication [main] No active profile set, falling back to 1 default profile: "default"
2022-11-02 10:11:00,011 INFO org.springframework.boot.StartupInfoLogger [main] Started TestLogApplication in 0.253 seconds (process running for 0.29)

Please give 3.0.0-SNAPSHOT a try and let us know if it resolves the problem.

Comment From: showpune

Hi @wilkinsona ,

I tried to deploy the image to 3 different K8S cluster ( linux ), and also ask 3 of my colleagues to run in docker desktop(windows) with "showpune/test-log:0.0.1-SNAPSHOT", all we got the same error:

   .   ____          _            __ _ _
  /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
 ( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
  \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
   '  |____| .__|_| |_|_| |_\__, | / / / /
  =========|_|==============|___/=/_/_/_/
  :: Spring Boot ::            (v3.0.0-RC1)

%PARSER_ERROR[d] %PARSER_ERROR[p] 1 --- [%PARSER_ERROR[t]] %PARSER_ERROR[logger] : %PARSER_ERROR[m]%PARSER_ERROR[n]
%PARSER_ERROR[d] %PARSER_ERROR[p] 1 --- [%PARSER_ERROR[t]] %PARSER_ERROR[logger] : %PARSER_ERROR[m]%PARSER_ERROR[n]
%PARSER_ERROR[d] %PARSER_ERROR[p] 1 --- [%PARSER_ERROR[t]] %PARSER_ERROR[logger] : %PARSER_ERROR[m]%PARSER_ERROR[n]

I am sure if it is related with env?

Comment From: wilkinsona

I see that you're still using 3.0.0-RC1. As I asked above, can you please try 3.0.0-SNAPSHOT?

Comment From: showpune

Hi @wilkinsona ,

I run "docker run showpune/test-log:3.0.0-SNAPSHOT", in my docker deskstop and Azure Kubernetes, and still get the error

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::       (v3.0.0-SNAPSHOT)

%PARSER_ERROR[d] %PARSER_ERROR[p] 1 --- [%PARSER_ERROR[t]] %PARSER_ERROR[logger] : %PARSER_ERROR[m]%PARSER_ERROR[n]%PARSER_ERROR[d] %PARSER_ERROR[p] 1 --- [%PARSER_ERROR[t]] %PARSER_ERROR[logger] : %PARSER_ERROR[m]%PARSER_ERROR[n]%PARSER_ERROR[d] %PARSER_ERROR[p] 1 --- [%PARSER_ERROR[t]] %PARSER_ERROR[logger] : %PARSER_ERROR[m]%PARSER_ERROR[n]

Comment From: wilkinsona

Thanks for trying 3.0.0-SNAPSHOT.

It looks like it must be related to your environment. PARSER_ERROR indicates that Logback couldn't create a converter for a conversion word in the configured pattern layout. Each word that caused a failure is shown in square brackets:

%PARSER_ERROR[d] %PARSER_ERROR[p] 1 --- [%PARSER_ERROR[t]] %PARSER_ERROR[logger] : %PARSER_ERROR[m]%PARSER_ERROR[n]

From this we can that the pattern was something like %d %p 1 --- [%t] %logger : %m%n. This does not match the pattern in your logback-spring.xml which is %d %p %C [%t] %m%n. The pattern that's being used is very close the Spring Boot's default pattern which, with some length information etc removed, is %d %p ${PID} --- [%t] %logger : %m%n%wEx. In the output you're seeing 1 will be ${PID}. %wEx is missing though.

My guess is that you app is using some custom Logback configuration during AOT processing and this configuration is then changing when running in a native image.

Perhaps there are some environment variables configured where you're running Maven that are interfering? I can reproduce some of the behaviour that you're seeing if I simulate this. First, I changed your logback-spring.xml to this:

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <appender name="Console"
              class="ch.qos.logback.core.ConsoleAppender">
        <layout class="ch.qos.logback.classic.PatternLayout">
            <Pattern>
                <Pattern>${PATTERN:-%d %p %C [%t] %m%n}</Pattern>
            </Pattern>
        </layout>
    </appender>

    <!-- LOG everything at INFO level -->
    <root level="info">
        <appender-ref ref="Console" />
    </root>
</configuration>

I then exported a PATTERN environment variable and built the native image:

export PATTERN="%d %p ${PID} --- [%t] %logger : %m%n"
mvn -Pnative native:compile

If I run the image with PATTERN still in place, logging works as expected:

$ target/test-log 

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::       (v3.0.0-SNAPSHOT)

2022-11-04 10:05:31,047 INFO  --- [main] com.example.testlog.TestLogApplication : Starting AOT-processed TestLogApplication using Java 17.0.5 with PID 63359 (/Users/awilkinson/dev/temp/test-log/target/test-log started by awilkinson in /Users/awilkinson/dev/temp/test-log)
2022-11-04 10:05:31,048 INFO  --- [main] com.example.testlog.TestLogApplication : No active profile set, falling back to 1 default profile: "default"
2022-11-04 10:05:31,053 INFO  --- [main] com.example.testlog.TestLogApplication : Started TestLogApplication in 0.016 seconds (process running for 0.028)

If I remove PATTERN and run the app again, no logging is produced:

$ export PATTERN=
$ target/test-log

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::       (v3.0.0-SNAPSHOT)

Please check the environment of the machine where you're running Maven for entries that may be interfering with Spring Boot's logging configuration. You could also check the format of the logging that's produced by process-aot. With my experiment above, it looked like this:

[INFO] --- spring-boot-maven-plugin:3.0.0-SNAPSHOT:process-aot (process-aot) @ test-log ---

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::       (v3.0.0-SNAPSHOT)

2022-11-04 10:03:23,566 INFO  --- [main] com.example.testlog.TestLogApplication : Starting TestLogApplication using Java 17.0.5 with PID 62763 (/Users/awilkinson/dev/temp/test-log/target/classes started by awilkinson in /Users/awilkinson/dev/temp/test-log)
2022-11-04 10:03:23,573 INFO  --- [main] com.example.testlog.TestLogApplication : No active profile set, falling back to 1 default profile: "default"

If it doesn't match the format configured in your logback-spring.xml file then you know that something is interfering with your logging configuration.

Comment From: showpune

It related with Graavm and I will close the issue

Comment From: crobster

It related with Graavm and I will close the issue

@showpune are you able to give any details on you dealt with this. I'm seeing the same issue. Thx

Comment From: pulsar-gupta

@wilkinsona I have tried the solution you mentioned above. However, I am still facing the same error. I am using spring-boot 3.0.0 (GA) with java 17.0.5 Using mvn -Pnative spring-boot:build-image to create image

 .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::                (v3.0.0)

%PARSER_ERROR[d] %PARSER_ERROR[p] 1 --- [%PARSER_ERROR[t]] %PARSER_ERROR[logger] : %PARSER_ERROR[m]%PARSER_ERROR[n]%PARSER_ERROR[d] %PARSER_ERROR[p] 1 --- [%PARSER_ERROR[t]] %PARSER_ERROR[logger] : %PARSER_ERROR[m]%PARSER_ERROR[n]%PARSER_ERROR[d] %PARSER_ERROR[p] 1 --- [%PARSER_ERROR[t]] %PARSER_ERROR[logger] : %PARSER_ERROR[m]%PARSER_ERROR[n]%PARSER_ERROR[d] %PARSER_ERROR[p] 1 --- [%PARSER_ERROR[t]] %PARSER_ERROR[logger] : %PARSER_ERROR[m]%PARSER_ERROR[n]%PARSER_ERROR[d] %PARSER_ERROR[p] 1 --- [%PARSER_ERROR[t]] %PARSER_ERROR[logger] : %PARSER_ERROR[m]%PARSER_ERROR[n]%PARSER_ERROR[d] %PARSER_ERROR[p] 1 --- [%PARSER_ERROR[t]] %PARSER_ERROR[logger] : %PARSER_ERROR[m]%PARSER_ERROR[n]%PARSER_ERROR[d] %PARSER_ERROR[p] 1 --- [%PARSER_ERROR[t]] %PARSER_ERROR[logger] : %PARSER_ERROR[m]%PARSER_ERROR[n]%PARSER_ERROR[d] %PARSER_ERROR[p] 1 --- [%PARSER_ERROR[t]] %PARSER_ERROR[logger] : %PARSER_ERROR[m]%PARSER_ERROR[n]%PARSER_ERROR[d] %PARSER_ERROR[p] 1 --- [%PARSER_ERROR[t]] %PARSER_ERROR[logger] : %PARSER_ERROR[m]%PARSER_ERROR[n]%PARSER_ERROR[d] %PARSER_ERROR[p] 1 --- [%PARSER_ERROR[t]] %PARSER_ERROR[logger] : %PARSER_ERROR[m]%PARSER_ERROR[n]%PARSER_ERROR[d] %PARSER_ERROR[p] 1 --- [%PARSER_ERROR[t]] %PARSER_ERROR[logger] : %PARSER_ERROR[m]%PARSER_ERROR[n]

Comment From: crobster

It related with Graavm and I will close the issue

@showpune are you able to give any details on you dealt with this. I'm seeing the same issue. Thx

33432 mentioned adding a plugin which dealt with the problem

which got me thinking...I would expect specifying the native profile would bring in that plugin via the parent pom. It is included in the parent pom but no phase is given.

According to the native plugin docs: https://graalvm.github.io/native-build-tools/latest/maven-plugin.html

Building native image without attaching to the package phase can be done by invoking the forking compile goal directly, e.g. mvn native:compile

Which works.

It also works giving the goal directly: org.graalvm.buildtoools:native-maven-plugin:add-reachability-metadata

SpringBoot Log doesn't work for java native image base on spring 3.0

33432 mentioned adding a plugin which dealt with the problem