spring-native icon indicating copy to clipboard operation
spring-native copied to clipboard

Add support for logback.xml configuration file

Open yschimke opened this issue 4 years ago • 27 comments

$ ./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 avatar Mar 17 '21 08:03 yschimke

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

yschimke avatar Mar 17 '21 08:03 yschimke

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?

sdeleuze avatar Mar 17 '21 10:03 sdeleuze

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

yschimke avatar Mar 17 '21 13:03 yschimke

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

sdeleuze avatar Mar 17 '21 17:03 sdeleuze

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.

cipley avatar Mar 19 '21 02:03 cipley

This temporary limitation is now documented.

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

sdeleuze avatar Mar 19 '21 14:03 sdeleuze

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

sdeleuze avatar Mar 22 '21 15:03 sdeleuze

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

richvim avatar Mar 24 '21 14:03 richvim

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 ?

celcius112 avatar Mar 31 '21 15:03 celcius112

Has this task been scheduled in the plan?

chenzhiguo avatar Mar 31 '21 16:03 chenzhiguo

@snicoll @bclozel Any thoughts on @celcius112 comment?

sdeleuze avatar Apr 01 '21 07:04 sdeleuze

This should be discussed in: https://github.com/spring-projects/spring-boot/issues/25847

bclozel avatar Apr 01 '21 07:04 bclozel

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).

cyraid avatar Apr 05 '21 20:04 cyraid

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

christian-draeger avatar Apr 20 '21 20:04 christian-draeger

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>

ranma2913 avatar May 14 '21 15:05 ranma2913

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 https://github.com/spring-projects/spring-boot/issues/25847 , I always thought logback.xml was a weird way to configure logback.

joeyslalom avatar May 17 '21 02:05 joeyslalom

@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 :)

celcius112 avatar May 19 '21 08:05 celcius112

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

frankkimm avatar Jun 23 '21 12:06 frankkimm

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 avatar Jul 01 '21 18:07 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 avatar Jul 01 '21 18:07 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.

phejl avatar Jul 02 '21 09:07 phejl

See #889 for a workaround.

sdeleuze avatar Jul 04 '21 20:07 sdeleuze

https://github.com/spring-projects-experimental/spring-native/commit/a9e661b4104a93c02cb8203f4422e082ad22f365 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

yschimke avatar Jul 05 '21 06:07 yschimke

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

sdeleuze avatar Jul 06 '21 09:07 sdeleuze

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

sdeleuze avatar Dec 06 '21 06:12 sdeleuze

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?

13940344135 avatar Feb 25 '22 05:02 13940344135

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 avatar Mar 15 '22 09:03 sdeleuze

This will be supported in Spring Boot 3 RC1 to be released tomorrow via https://github.com/spring-projects/spring-boot/commit/4a76fbf93c03b45917f06c65bbd877ac160a6149 thanks to @wilkinsona.

sdeleuze avatar Oct 19 '22 20:10 sdeleuze