Add support for logback.xml configuration file

[yschimke]

$ ./gradlew bootBuildImage
...
    [creator]     javax.xml.parsers.FactoryFinder was unintentionally initialized at build time. org.slf4j.impl.StaticLoggerBinder caused initialization of this class with the following trace:
    [creator]           at javax.xml.parsers.FactoryFinder.<clinit>(FactoryFinder.java:46)
    [creator]           at javax.xml.parsers.SAXParserFactory.newInstance(SAXParserFactory.java:147)
    [creator]           at ch.qos.logback.core.joran.event.SaxEventRecorder.buildSaxParser(SaxEventRecorder.java:79)
    [creator]           at ch.qos.logback.core.joran.event.SaxEventRecorder.recordEvents(SaxEventRecorder.java:57)
    [creator]           at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:151)
    [creator]           at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:110)
    [creator]           at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:53)
    [creator]           at ch.qos.logback.classic.util.ContextInitializer.configureByResource(ContextInitializer.java:75)
    [creator]           at ch.qos.logback.classic.util.ContextInitializer.autoConfig(ContextInitializer.java:150)
    [creator]           at org.slf4j.impl.StaticLoggerBinder.init(StaticLoggerBinder.java:84)
    [creator]           at org.slf4j.impl.StaticLoggerBinder.<clinit>(StaticLoggerBinder.java:55)

[yschimke]

I'm testing now without this but I believe the codepath is when it hit src/main/resources/logback.xml

[sdeleuze]

Not an easy one:

Error: Classes that should be initialized at run time got initialized during image building:
 javax.xml.parsers.FactoryFinder was unintentionally initialized at build time. org.slf4j.impl.StaticLoggerBinder caused initialization of this class with the following trace: 
	at javax.xml.parsers.FactoryFinder.<clinit>(FactoryFinder.java:45)
	at javax.xml.parsers.SAXParserFactory.newInstance(SAXParserFactory.java:127)
	at ch.qos.logback.core.joran.event.SaxEventRecorder.buildSaxParser(SaxEventRecorder.java:79)
	at ch.qos.logback.core.joran.event.SaxEventRecorder.recordEvents(SaxEventRecorder.java:57)
	at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:151)
	at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:110)
	at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:53)
	at ch.qos.logback.classic.util.ContextInitializer.configureByResource(ContextInitializer.java:75)
	at ch.qos.logback.classic.util.ContextInitializer.autoConfig(ContextInitializer.java:150)
	at org.slf4j.impl.StaticLoggerBinder.init(StaticLoggerBinder.java:84)
	at org.slf4j.impl.StaticLoggerBinder.<clinit>(StaticLoggerBinder.java:55)

We do our best to limit build time initialization but with SLF4J that's hard to avoid and here SLF4J build time init trigger logback SaxEventRecorder which performs javax.xml.parsers.FactoryFinder static init at build time.

Trying to intialize javax.xml.parsers.FactoryFinder at build time requires to configure a lot of other classes initialized at build time too so that seems a dead end to me.

Any thoughts @aclement?

[yschimke]

It worked for me just by deleting the file (I got further), so I'm not blocked.

[sdeleuze]

I move this issue to 0.10 since solving that will require deeper changes.

[cipley]

Hi,

I stumble upon this issue as well, and want to add some points;
It seems like having the logback file logback-spring.xml will result in below error:

Logging system failed to initialize using configuration from 'null'
java.lang.IllegalStateException: Could not initialize Logback logging from classpath:logback-spring.xml
        at org.springframework.boot.logging.logback.LogbackLoggingSystem.loadConfiguration(LogbackLoggingSystem.java:168)
        at org.springframework.boot.logging.AbstractLoggingSystem.initializeWithConventions(AbstractLoggingSystem.java:80)
        at org.springframework.boot.logging.AbstractLoggingSystem.initialize(AbstractLoggingSystem.java:60)
        at org.springframework.boot.logging.logback.LogbackLoggingSystem.initialize(LogbackLoggingSystem.java:132)
        at org.springframework.boot.context.logging.LoggingApplicationListener.initializeSystem(LoggingApplicationListener.java:312)
        at org.springframework.boot.context.logging.LoggingApplicationListener.initialize(LoggingApplicationListener.java:281)
        at org.springframework.boot.context.logging.LoggingApplicationListener.onApplicationEnvironmentPreparedEvent(LoggingApplicationListener.java:239)
        at org.springframework.boot.context.logging.LoggingApplicationListener.onApplicationEvent(LoggingApplicationListener.java:216)
        at org.springframework.context.event.SimpleApplicationEventMulticaster.doInvokeListener(SimpleApplicationEventMulticaster.java:203)
        at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:196)
        at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:170)
        at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:148)
        at org.springframework.boot.context.event.EventPublishingRunListener.environmentPrepared(EventPublishingRunListener.java:82)
        at org.springframework.boot.SpringApplicationRunListeners.lambda$environmentPrepared$2(SpringApplicationRunListeners.java:63)
        at java.util.ArrayList.forEach(ArrayList.java:1259)
        at org.springframework.boot.SpringApplicationRunListeners.doWithListeners(SpringApplicationRunListeners.java:117)
        at org.springframework.boot.SpringApplicationRunListeners.doWithListeners(SpringApplicationRunListeners.java:111)
        at org.springframework.boot.SpringApplicationRunListeners.environmentPrepared(SpringApplicationRunListeners.java:62)
        at org.springframework.boot.SpringApplication.prepareEnvironment(SpringApplication.java:362)
        at org.springframework.boot.SpringApplication.run(SpringApplication.java:320)
        at org.springframework.boot.SpringApplication.run(SpringApplication.java:1311)
        at org.springframework.boot.SpringApplication.run(SpringApplication.java:1300)
        at i.c.t.d.b.n.api.Application.main(Application.java:18)
Caused by: ch.qos.logback.core.LogbackException: Unexpected filename extension of file [resource:logback-spring.xml]. Should be either .groovy or .xml
        at ch.qos.logback.classic.util.ContextInitializer.configureByResource(ContextInitializer.java:58)
        at org.springframework.boot.logging.logback.LogbackLoggingSystem.configureByResourceUrl(LogbackLoggingSystem.java:191)
        at org.springframework.boot.logging.logback.LogbackLoggingSystem.loadConfiguration(LogbackLoggingSystem.java:165)
        ... 22 more

Which is quite odd since the logback file is actually have the correct extensions.

While in my case, when using logback.xml logback file, it will result in build error (I'm using maven btw);

...
[INFO]     [creator]     Error: Classes that should be initialized at run time got initialized during image building:
[INFO]     [creator]      org.springframework.boot.ansi.AnsiOutput was unintentionally initialized at build time. To see why org.springframework.boot.ansi.AnsiOutput got initialized use --trace-class-initialization=org.springframework.boot.ansi.AnsiOutput
[INFO]     [creator]     org.springframework.boot.logging.logback.ColorConverter was unintentionally initialized at build time. To see why org.springframework.boot.logging.logback.ColorConverter got initialized use --trace-class-initialization=org.springframework.boot.logging.logback.ColorConverter
[INFO]     [creator]
[INFO]     [creator]     Error: Use -H:+ReportExceptionStackTraces to print stacktrace of underlying exception
[INFO]     [creator]     Error: Image build request failed with exit status 1
[INFO]     [creator]     unable to invoke layer creator
[INFO]     [creator]     unable to contribute native-image layer
[INFO]     [creator]     error running build
[INFO]     [creator]     exit status 1
[INFO]     [creator]     ERROR: failed to build: exit status 1
[INFO] ------------------------------------------------------------------------
[INFO] BUILD FAILURE
[INFO] ------------------------------------------------------------------------
[INFO] Total time:  02:51 min
[INFO] Finished at: 2021-03-19T05:32:17+07:00
[INFO] ------------------------------------------------------------------------
[ERROR] Failed to execute goal org.springframework.boot:spring-boot-maven-plugin:2.4.3:build-image (default-cli) on project networkprofile-bs-api: Execution default-cli of goal org.springframework.boot:spring-boot-maven-plugin:2.4.3:build-image failed: Builder lifecycle 'creator' failed with status code 145 -> [Help 1]
[ERROR]
[ERROR] To see the full stack trace of the errors, re-run Maven with the -e switch.
[ERROR] Re-run Maven using the -X switch to enable full debug logging.
[ERROR]
[ERROR] For more information about the errors and possible solutions, please read the following articles:
[ERROR] [Help 1] http://cwiki.apache.org/confluence/display/MAVEN/PluginExecutionException

and yes, deleting the logback file causes the issue to disappear.

[sdeleuze]

This temporary limitation is now documented.

When we fix that, let's make sure <springProperty /> is supported as described in #607.

[sdeleuze]

logback.xml support seems more complicated than I thought originally, especially with Janino (a java compiler) involved.

[richvim]

Ran into this one while upgrading to 0.9.x. Did not occur in previous versions.

[celcius112]

I am wondering whether Spring Boot should add more documentation (or features) about Logback's Configurator which allows for programmatic configuration instead of XML configuration.
Favoring programmatic configuration would probably be a good way to mitigate this issue, but I'm having some problems finding good documentation for extending Spring Boot configuration.

What do you think ?

[chenzhiguo]

Has this task been scheduled in the plan?

[sdeleuze]

@snicoll @bclozel Any thoughts on @celcius112 comment?

[bclozel]

This should be discussed in: spring-projects/spring-boot#25847

[cyraid]

This was a blocker for me. I wanted to convert to native but our projects need the logback-spring.xml and springProperty and also the compiler (for if blocks/statements).

A way forward might be to implement a new configuration file format but with native 'if' support without using janino compiler? Perhaps a more lean method of setting your appenders (that is somewhat compatible with logback on a basic level).

[christian-draeger]

same error as @cipley over here with version "0.9.2"

[ranma2913]

Having the same issues with my project. So far we've been able to copy a standard logback-spring.xml between our projects. This enables our Splunk HTTP Appender. We're using the follwoing code and other springProperty placeholders:

    <!-- Import Non-Production Spring Properties & Set Defaults -->
    <springProperty name="LOGGING_SPLUNK_URL" source="logging.splunk.url" defaultValue="---"/>
    <springProperty name="LOGGING_SPLUNK_TOKEN" source="logging.splunk.token" defaultValue="---"/>

    <springProfile name="prod">
        <!-- configuration to be enabled when the "prod" profile is active -->
        <!-- Import Production Spring Properties & Set Defaults -->
        <springProperty name="LOGGING_SPLUNK_URL" source="logging.splunk.url" defaultValue="----"/>
        <springProperty name="LOGGING_SPLUNK_TOKEN" source="logging.splunk.token" defaultValue="---"/>
    </springProfile>

[joeyslalom]

Also fails for me with version 0.9.2. After seeing Logback is supported, but not configuration with logback.xml
I wondered if configuration via logback.groovy would work. It does not build via ./gradlew bootBuildImage:

Error: Classes that should be initialized at run time got initialized during image building:
[snip]
quite a lot of org.codehaus.groovy.NAME was unintentionally initialized at build time. To see why 
[snip]

Not advocating for logback.groovy, but I would have used it to workaround this issue. The basic customization via application.properties is not sufficient. I'm forward to spring-projects/spring-boot#25847 , I always thought logback.xml was a weird way to configure logback.

[celcius112]

@joeyslalom don't hesitate to add a 👍 to the issue spring-projects/spring-boot#25847. If we show that we would like this feature the spring boot team will be more motivated to do it :)

[frankkimm]

same error as @cipley over here with version "0.10.0"

[phejl]

Hm, now I'm wondering what is the reproducible case :) What I did is I enabled xml support removeXmlSupport = false added type hints to all the different logback's converters, encoders and policies my app is using and now I'm able to run app just fine with my xml config including springProfile using -Dlogging.config=/path/to/my/logback-config.xml. No error during build or runtime.

[phejl]

With janino on CP and janino if condition in xml file (as far as I can tell I've added necessary TypeHints) the generated image just exit without any message with exit code 1.

Hm, Janino creates class at runtime and loads it. That could be the cause.

[phejl]

Hm, now I'm wondering what is the reproducible case

I see now it happens in case logback.xml is embedded in the application.

[sdeleuze]

See #889 for a workaround.

[yschimke]

a9e661b assume this feeds here https://docs.spring.io/spring-native/docs/current/reference/htmlsingle/#_application_failed_to_start_when_running_code_mvn_spring_boot_run_code eventually

[sdeleuze]

See https://docs.spring.io/spring-native/docs/current-SNAPSHOT/reference/htmlsingle/#logback-workaround/

[sdeleuze]

See also my recent update of Logback support documentation with explain how to specify configuration with logback-config.xml at runtime.

[13940344135]

I created ch.qos.logback.classic.spi.Configurator file, CustomConfigurator class, and added @InitializationHint annotation as described in the documentation below.
10.2.3. How can I configure programmatically Logback as a logback.xml alternative?
But anyway, when I build, I get the following error,

> Task :nativeCompile
Toolchain detection is disabled, will use GraalVM from C:\graalvm-ce-java11-21.3.0.
[native-image-plugin] Using executable path: C:\graalvm-ce-java11-21.3.0\bin\native-image.cmd
[mystore:14228]    classlist:   3,766.58 ms,  1.19 GB
[mystore:14228]        (cap):   2,916.83 ms,  1.19 GB
Warning: Could not register org.springframework.boot.liquibase.LiquibaseChangelogMissingFailureAnalyzer: allDeclaredConstructors for reflection. Reason: java.lang.NoClassDefFoundError: liquibase/exception/ChangeLogParseException.
[mystore:14228]        setup:   4,625.32 ms,  1.19 GB
The bundle named: org.apache.tomcat.util.threads.res.LocalStrings, has not been found. If the bundle is part of a module, verify the bundle name is a fully qualified class name. Otherwise verify the bundle path is accessible in the classpath.
To see how the classes got initialized, use --trace-class-initialization=org.springframework.boot.logging.logback.ColorConverter
[mystore:14228]     analysis:   7,318.84 ms,  2.98 GB
Error: Classes that should be initialized at run time got initialized during image building:
 org.springframework.boot.logging.logback.ColorConverter was unintentionally initialized at build time. To see why org.springframework.boot.logging.logback.ColorConverter got initialized use --trace-class-initialization=org.springframework.boot.logging.logback.ColorConverter

Error: Use -H:+ReportExceptionStackTraces to print stacktrace of underlying exception
[mystore:14228]      [total]:  15,945.31 ms,  2.98 GB
# Printing build artifacts to: C:\workspace\mystore\build\native\nativeCompile\mystore.build_artifacts.txt
Error: Image build request failed with exit status 1

> Task :nativeCompile FAILED

FAILURE: Build failed with an exception.

* What went wrong:
Execution failed for task ':nativeCompile'.
> Process 'command 'C:\graalvm-ce-java11-21.3.0\bin\native-image.cmd'' finished with non-zero exit value 1

* Try:
> Run with --stacktrace option to get the stack trace.
> Run with --info or --debug option to get more log output.
> Run with --scan to get full insights.

* Get more help at https://help.gradle.org

BUILD FAILED in 36s
10 actionable tasks: 10 executed

am I missing something?

[sdeleuze]

Indeed, I can reproduce. Since embedded logback-spring.xml is now a better way to solve this as discussed here, I will just remove this programmatic Logback configuration from the documentation.

[sdeleuze]

This will be supported in Spring Boot 3 RC1 to be released tomorrow via spring-projects/spring-boot@4a76fbf thanks to @wilkinsona.