ConsoleAppender does not work in native mode

[arolfes]

Hello @stuartwdouglas ,

When the application is compiled native, the pattern in ConsoleAppender does not work. Everything is fine, when running in JVM mode.

I created an example here, to reproduce it.

Versions

Quarkus=2.14.3.Final
quarkus-logging-logback=0.13.0
GraalVm=22.3.0
Java=17

Logback.Xml

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="false">
  <appender name="Appender" class="ch.qos.logback.core.ConsoleAppender">
    <layout class="ch.qos.logback.classic.PatternLayout">
      <Pattern>
        %black(%d{ISO8601}) [%blue(%t)] %highlight(%-5level)[ traceId=%X{traceId} spanId=%X{spanId} ] %yellow(%C{1}): %msg%n%throwable
      </Pattern>
    </layout>
  </appender>

  <root>
    <level value="INFO"/>
    <appender-ref ref="Appender"/>
  </root>

</configuration>

Example Log from JVM Mode

arl@fedora ~/sources/quarkus/quarkus-logback-native $ ./gradlew quarkusDev

> Task :quarkusDev
Listening for transport dt_socket at address: 5005
Press [h] for more options>
Tests paused
Press [r] to resume testing, [h] for more options>
Press [r] to resume testing, [o] Toggle test output, [h] for more options>
07:46:19,579 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set
07:46:19,582 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender$$delayed]
07:46:19,583 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [Appender]
07:46:19,591 |-WARN in ch.qos.logback.core.ConsoleAppender$$delayed[Appender] - This appender no longer admits a layout as a sub-component, set an encoder instead.
07:46:19,591 |-WARN in ch.qos.logback.core.ConsoleAppender$$delayed[Appender] - To ensure compatibility, wrapping your layout in LayoutWrappingEncoder.
07:46:19,591 |-WARN in ch.qos.logback.core.ConsoleAppender$$delayed[Appender] - See also http://logback.qos.ch/codes.html#layoutInsteadOfEncoder for details
07:46:19,591 |-INFO in ch.qos.logback.classic.joran.action.LevelAction - ROOT level set to INFO
07:46:19,591 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [Appender] to Logger[ROOT]
07:46:19,591 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.

2022-12-14 07:46:19,884 [Quarkus Main Thread] INFO [ traceId= spanId= ] i.q.b.r.Timing: quarkus-logback-native 1.0.0-SNAPSHOT on JVM (powered by Quarkus 2.14.3.Final) started in 1.639s. Listening on: http://localhost:8080
2022-12-14 07:46:19,887 [Quarkus Main Thread] INFO [ traceId= spanId= ] i.q.b.r.Timing: Profile dev activated. Live Coding activated.
2022-12-14 07:46:19,888 [Quarkus Main Thread] INFO [ traceId= spanId= ] i.q.b.r.Timing: Installed features: [cdi, logging-logback, resteasy, smallrye-context-propagation, vertx]
2022-12-14 07:49:04,056 [executor-thread-0] INFO [ traceId= spanId= ] o.a.GreetingResource: Hello Logback

Example Log from Native Mode

arl@fedora ~/sources/quarkus/quarkus-logback-native $ build/quarkus-logback-native-1.0.0-SNAPSHOT-runner 
%PARSER_ERROR[black] [%PARSER_ERROR[blue]] %PARSER_ERROR[highlight][ traceId=%PARSER_ERROR[X] spanId=%PARSER_ERROR[X] ] %PARSER_ERROR[yellow]: %PARSER_ERROR[msg]%PARSER_ERROR[n]%PARSER_ERROR[throwable]%PARSER_ERROR[black] [%PARSER_ERROR[blue]] %PARSER_ERROR[highlight][ traceId=%PARSER_ERROR[X] spanId=%PARSER_ERROR[X] ] %PARSER_ERROR[yellow]: %PARSER_ERROR[msg]%PARSER_ERROR[n]%PARSER_ERROR[throwable]%PARSER_ERROR[black] [%PARSER_ERROR[blue]] %PARSER_ERROR[highlight][ traceId=%PARSER_ERROR[X] spanId=%PARSER_ERROR[X] ] %PARSER_ERROR[yellow]: %PARSER_ERROR[msg]%PARSER_ERROR[n]%PARSER_ERROR[throwable]

%PARSER_ERROR[black] [%PARSER_ERROR[blue]] %PARSER_ERROR[highlight][ traceId=%PARSER_ERROR[X] spanId=%PARSER_ERROR[X] ] %PARSER_ERROR[yellow]: %PARSER_ERROR[msg]%PARSER_ERROR[n]%PARSER_ERROR[throwable]

Log from native Compile Process

arl@fedora ~/sources/quarkus/quarkus-logback-native $ ./gradlew build -Dquarkus.package.type=native
Starting a Gradle Daemon, 1 stopped Daemon could not be reused, use --status for details
========================================================================================================================
GraalVM Native Image: Generating 'quarkus-logback-native-1.0.0-SNAPSHOT-runner' (executable)...
========================================================================================================================
[1/7] Initializing...                                                                                    (5.3s @ 0.16GB)
 Version info: 'GraalVM 22.3.0 Java 17 CE'
 Java version info: '17.0.5+8-jvmci-22.3-b08'
 C compiler: gcc (redhat, x86_64, 12.2.1)
 Garbage collector: Serial GC
 3 user-specific feature(s)
 - io.quarkus.runner.Feature: Auto-generated class by Quarkus from the existing extensions
 - io.quarkus.runtime.graal.DisableLoggingFeature: Disables INFO logging during the analysis phase for the [org.jboss.threads] categories
 - io.quarkus.runtime.graal.ResourcesFeature: Register each line in META-INF/quarkus-native-resources.txt as a resource on Substrate VM
07:52:21,011 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set
07:52:21,038 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender$$delayed]
07:52:21,039 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [Appender]
07:52:21,043 |-WARN in ch.qos.logback.core.ConsoleAppender$$delayed[Appender] - This appender no longer admits a layout as a sub-component, set an encoder instead.
07:52:21,043 |-WARN in ch.qos.logback.core.ConsoleAppender$$delayed[Appender] - To ensure compatibility, wrapping your layout in LayoutWrappingEncoder.
07:52:21,043 |-WARN in ch.qos.logback.core.ConsoleAppender$$delayed[Appender] - See also http://logback.qos.ch/codes.html#layoutInsteadOfEncoder for details
07:52:21,043 |-INFO in ch.qos.logback.classic.joran.action.LevelAction - ROOT level set to INFO
07:52:21,043 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [Appender] to Logger[ROOT]
07:52:21,043 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.

[2/7] Performing analysis...  [*******]                                                                 (25.8s @ 3.28GB)
  10,647 (89.34%) of 11,917 classes reachable
  15,295 (58.22%) of 26,273 fields reachable
  52,427 (55.21%) of 94,959 methods reachable
     468 classes,   122 fields, and 2,128 methods registered for reflection
      63 classes,    68 fields, and    55 methods registered for JNI access
       4 native libraries: dl, pthread, rt, z
[3/7] Building universe...                                                                               (3.9s @ 1.45GB)
[4/7] Parsing methods...      [**]                                                                       (2.7s @ 4.51GB)
[5/7] Inlining methods...     [***]                                                                      (1.7s @ 1.92GB)
[6/7] Compiling methods...    [*****]                                                                   (22.0s @ 3.10GB)
[7/7] Creating image...                                                                                  (3.4s @ 4.50GB)
  19.66MB (48.32%) for code area:    33,584 compilation units
  20.72MB (50.92%) for image heap:  265,698 objects and 10 resources
 320.80KB ( 0.77%) for other data
  40.69MB in total
------------------------------------------------------------------------------------------------------------------------
Top 10 packages in code area:                               Top 10 object types in image heap:
   1.62MB sun.security.ssl                                     4.38MB byte[] for code metadata
 968.05KB java.util                                            2.52MB java.lang.Class
 729.28KB java.lang.invoke                                     2.45MB java.lang.String
 718.49KB com.sun.crypto.provider                              2.16MB byte[] for general heap data
 450.56KB sun.security.x509                                    1.92MB byte[] for java.lang.String
 444.83KB java.lang                                          914.98KB com.oracle.svm.core.hub.DynamicHubCompanion
 401.21KB java.util.concurrent                               644.77KB java.util.HashMap$Node
 398.19KB java.io                                            541.26KB byte[] for reflection metadata
 394.59KB io.netty.buffer                                    481.15KB java.lang.String[]
 338.80KB io.netty.handler.codec.http2                       394.54KB byte[] for embedded resources
  13.06MB for 399 more packages                                4.10MB for 2582 more object types
------------------------------------------------------------------------------------------------------------------------
                        2.7s (3.8% of total time) in 28 GCs | Peak RSS: 5.99GB | CPU load: 8.38
------------------------------------------------------------------------------------------------------------------------
Produced artifacts:
 /home/arl/sources/quarkus/quarkus-logback-native/build/quarkus-logback-native-1.0.0-SNAPSHOT-native-image-source-jar/quarkus-logback-native-1.0.0-SNAPSHOT-runner (executable)
 /home/arl/sources/quarkus/quarkus-logback-native/build/quarkus-logback-native-1.0.0-SNAPSHOT-native-image-source-jar/quarkus-logback-native-1.0.0-SNAPSHOT-runner-build-output-stats.json (json)
 /home/arl/sources/quarkus/quarkus-logback-native/build/quarkus-logback-native-1.0.0-SNAPSHOT-native-image-source-jar/quarkus-logback-native-1.0.0-SNAPSHOT-runner-timing-stats.json (raw)
 /home/arl/sources/quarkus/quarkus-logback-native/build/quarkus-logback-native-1.0.0-SNAPSHOT-native-image-source-jar/quarkus-logback-native-1.0.0-SNAPSHOT-runner.build_artifacts.txt (txt)
========================================================================================================================
Finished generating 'quarkus-logback-native-1.0.0-SNAPSHOT-runner' in 1m 9s.

BUILD SUCCESSFUL in 1m 20s
9 actionable tasks: 2 executed, 7 up-to-date