When there is an error raised during logback initialization, spring boot application crashes without displaying any message.
In my case, the error was caused by a missing gradle dependency org.codehaus.janino:janino. Here is the content of my logback.xml file: logback.txt
Library org.codehaus.janino:janino is essential dependency for this logback config to work properly. Specifically for evaluating expressions in the EvaluatorFilter. Another essential dependencies for this config are ch.qos.logback.contrib:logback-json-classic and ch.qos.logback.contrib:logback-jackson.
I internally solved this issue by registering a custom SpringApplicationRunListener where the failed method is overridden. This method is implemented to dump the stacktrace directly into stderr. Then I can see the NoClassDefFound error as expected.
Similar issue: https://github.com/spring-projects/spring-boot/issues/10711
I think that there should be displayed some information about the reason of the crash even in this circumstances. Thank you.
Comment From: philwebb
When I add you config to an empty project I get the following output:
17:43:07,089 |-INFO in ch.qos.logback.classic.LoggerContext[default] - This is logback-classic version 1.4.14
17:43:07,090 |-INFO in ch.qos.logback.classic.util.ContextInitializer@75881071 - Here is a list of configurators discovered as a service, by rank:
17:43:07,090 |-INFO in ch.qos.logback.classic.util.ContextInitializer@75881071 - org.springframework.boot.logging.logback.RootLogLevelConfigurator
17:43:07,090 |-INFO in ch.qos.logback.classic.util.ContextInitializer@75881071 - They will be invoked in order until ExecutionStatus.DO_NOT_INVOKE_NEXT_IF_ANY is returned.
17:43:07,090 |-INFO in ch.qos.logback.classic.util.ContextInitializer@75881071 - Constructed configurator of type class org.springframework.boot.logging.logback.RootLogLevelConfigurator
17:43:07,098 |-INFO in ch.qos.logback.classic.util.ContextInitializer@75881071 - org.springframework.boot.logging.logback.RootLogLevelConfigurator.configure() call lasted 0 milliseconds. ExecutionStatus=INVOKE_NEXT_IF_ANY
17:43:07,098 |-INFO in ch.qos.logback.classic.util.ContextInitializer@75881071 - Trying to configure with ch.qos.logback.classic.joran.SerializedModelConfigurator
17:43:07,099 |-INFO in ch.qos.logback.classic.util.ContextInitializer@75881071 - Constructed configurator of type class ch.qos.logback.classic.joran.SerializedModelConfigurator
17:43:07,100 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.scmo]
17:43:07,101 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.scmo]
17:43:07,101 |-INFO in ch.qos.logback.classic.util.ContextInitializer@75881071 - ch.qos.logback.classic.joran.SerializedModelConfigurator.configure() call lasted 2 milliseconds. ExecutionStatus=INVOKE_NEXT_IF_ANY
17:43:07,101 |-INFO in ch.qos.logback.classic.util.ContextInitializer@75881071 - Trying to configure with ch.qos.logback.classic.util.DefaultJoranConfigurator
17:43:07,101 |-INFO in ch.qos.logback.classic.util.ContextInitializer@75881071 - Constructed configurator of type class ch.qos.logback.classic.util.DefaultJoranConfigurator
17:43:07,101 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
17:43:07,103 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/Users/pwebb/projects/spring-boot/samples/gh-38862/nested-jars-issue/bin/main/logback.xml]
17:43:07,160 |-INFO in ch.qos.logback.classic.model.processor.ConfigurationModelHandlerFull - Registering a new ReconfigureOnChangeTask ReconfigureOnChangeTask(born:1703122987159)
17:43:07,160 |-INFO in ch.qos.logback.classic.model.processor.ConfigurationModelHandlerFull - Will scan for changes in [file:/Users/pwebb/projects/spring-boot/samples/gh-38862/nested-jars-issue/bin/main/logback.xml]
17:43:07,160 |-INFO in ch.qos.logback.classic.model.processor.ConfigurationModelHandlerFull - Setting ReconfigureOnChangeTask scanning period to 30 seconds
17:43:07,163 |-INFO in ch.qos.logback.core.model.processor.StatusListenerModelHandler - Added status listener of type [ch.qos.logback.core.status.OnConsoleStatusListener]
17:43:07,173 |-WARN in ch.qos.logback.core.model.processor.ImplicitModelHandler - Ignoring unknown property [springProperty] in [ch.qos.logback.classic.LoggerContext]
17:43:07,174 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - Processing appender named [stdout]
17:43:07,174 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
17:43:07,178 |-ERROR in ch.qos.logback.core.model.processor.ImplicitModelHandler - Could not create component [layout] of type [ch.qos.logback.contrib.json.classic.JsonLayout] java.lang.ClassNotFoundException: ch.qos.logback.contrib.json.classic.JsonLayout
at java.lang.ClassNotFoundException: ch.qos.logback.contrib.json.classic.JsonLayout
at at java.base/jdk.internal.loader.BuiltinClassLoader.loadClass(BuiltinClassLoader.java:641)
at at java.base/jdk.internal.loader.ClassLoaders$AppClassLoader.loadClass(ClassLoaders.java:188)
at at java.base/java.lang.ClassLoader.loadClass(ClassLoader.java:520)
at at ch.qos.logback.core.util.Loader.loadClass(Loader.java:132)
at at ch.qos.logback.core.model.processor.ImplicitModelHandler.doComplex(ImplicitModelHandler.java:134)
at at ch.qos.logback.core.model.processor.ImplicitModelHandler.handle(ImplicitModelHandler.java:94)
at at ch.qos.logback.core.model.processor.DefaultProcessor.secondPhaseTraverse(DefaultProcessor.java:241)
at at ch.qos.logback.core.model.processor.DefaultProcessor.secondPhaseTraverse(DefaultProcessor.java:253)
at at ch.qos.logback.core.model.processor.DefaultProcessor.secondPhaseTraverse(DefaultProcessor.java:253)
at at ch.qos.logback.core.model.processor.DefaultProcessor.secondPhaseTraverse(DefaultProcessor.java:253)
at at ch.qos.logback.core.model.processor.DefaultProcessor.traversalLoop(DefaultProcessor.java:90)
at at ch.qos.logback.core.model.processor.DefaultProcessor.process(DefaultProcessor.java:106)
at at ch.qos.logback.core.joran.GenericXMLConfigurator.processModel(GenericXMLConfigurator.java:208)
at at ch.qos.logback.core.joran.GenericXMLConfigurator.doConfigure(GenericXMLConfigurator.java:170)
at at ch.qos.logback.core.joran.GenericXMLConfigurator.doConfigure(GenericXMLConfigurator.java:122)
at at ch.qos.logback.core.joran.GenericXMLConfigurator.doConfigure(GenericXMLConfigurator.java:65)
at at ch.qos.logback.classic.util.DefaultJoranConfigurator.configureByResource(DefaultJoranConfigurator.java:68)
at at ch.qos.logback.classic.util.DefaultJoranConfigurator.configure(DefaultJoranConfigurator.java:35)
at at ch.qos.logback.classic.util.ContextInitializer.invokeConfigure(ContextInitializer.java:128)
at at ch.qos.logback.classic.util.ContextInitializer.autoConfig(ContextInitializer.java:103)
at at ch.qos.logback.classic.util.ContextInitializer.autoConfig(ContextInitializer.java:66)
at at ch.qos.logback.classic.spi.LogbackServiceProvider.initializeLoggerContext(LogbackServiceProvider.java:52)
at at ch.qos.logback.classic.spi.LogbackServiceProvider.initialize(LogbackServiceProvider.java:41)
at at org.slf4j.LoggerFactory.bind(LoggerFactory.java:195)
at at org.slf4j.LoggerFactory.performInitialization(LoggerFactory.java:182)
at at org.slf4j.LoggerFactory.getProvider(LoggerFactory.java:490)
at at org.slf4j.LoggerFactory.getILoggerFactory(LoggerFactory.java:476)
at at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:425)
at at org.apache.commons.logging.LogAdapter$Slf4jAdapter.createLocationAwareLog(LogAdapter.java:121)
at at org.apache.commons.logging.LogAdapter.createLog(LogAdapter.java:95)
at at org.apache.commons.logging.LogFactory.getLog(LogFactory.java:67)
at at org.apache.commons.logging.LogFactory.getLog(LogFactory.java:59)
at at org.springframework.boot.SpringApplication.<clinit>(SpringApplication.java:202)
at at com.example.demo.DemoApplication.main(DemoApplication.java:14)
17:43:07,179 |-WARN in ch.qos.logback.core.model.processor.ImplicitModelHandler - Ignoring unknown property [jsonFormatter] in [ch.qos.logback.core.encoder.LayoutWrappingEncoder]
17:43:07,179 |-WARN in ch.qos.logback.core.model.processor.ImplicitModelHandler - Ignoring unknown property [timestampFormat] in [ch.qos.logback.core.encoder.LayoutWrappingEncoder]
17:43:07,179 |-WARN in ch.qos.logback.core.model.processor.ImplicitModelHandler - Ignoring unknown property [appendLineSeparator] in [ch.qos.logback.core.encoder.LayoutWrappingEncoder]
17:43:07,179 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - Processing appender named [RollingFileTrace]
17:43:07,179 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - About to instantiate appender of type [ch.qos.logback.core.rolling.RollingFileAppender]
17:43:07,185 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy@1300393335 - No compression will be used
17:43:07,186 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy@1300393335 - Will use the pattern LOG_DIRECTORY_TRACE_IS_UNDEFINED/hrp-webserver-trace-%d{yyyy-MM-dd, UTC}.log for the active file
17:43:07,197 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - The date pattern is 'yyyy-MM-dd' from file name pattern 'LOG_DIRECTORY_TRACE_IS_UNDEFINED/hrp-webserver-trace-%d{yyyy-MM-dd, UTC}.log'.
17:43:07,198 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - Roll-over at midnight.
17:43:07,201 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - Setting initial period to 2023-12-21T01:43:07.200Z
17:43:07,202 |-INFO in ch.qos.logback.core.model.processor.ImplicitModelHandler - Assuming default type [ch.qos.logback.classic.boolex.JaninoEventEvaluator] for [evaluator] property
Exception in thread "main" java.lang.NoClassDefFoundError: org/codehaus/janino/ScriptEvaluator
at ch.qos.logback.core.boolex.JaninoEventEvaluatorBase.start(JaninoEventEvaluatorBase.java:57)
at ch.qos.logback.core.model.processor.ImplicitModelHandler.postHandleComplex(ImplicitModelHandler.java:208)
at ch.qos.logback.core.model.processor.ImplicitModelHandler.postHandle(ImplicitModelHandler.java:186)
at ch.qos.logback.core.model.processor.DefaultProcessor.secondPhaseTraverse(DefaultProcessor.java:257)
at ch.qos.logback.core.model.processor.DefaultProcessor.secondPhaseTraverse(DefaultProcessor.java:253)
at ch.qos.logback.core.model.processor.DefaultProcessor.secondPhaseTraverse(DefaultProcessor.java:253)
at ch.qos.logback.core.model.processor.DefaultProcessor.secondPhaseTraverse(DefaultProcessor.java:253)
at ch.qos.logback.core.model.processor.DefaultProcessor.traversalLoop(DefaultProcessor.java:90)
at ch.qos.logback.core.model.processor.DefaultProcessor.process(DefaultProcessor.java:106)
at ch.qos.logback.core.joran.GenericXMLConfigurator.processModel(GenericXMLConfigurator.java:208)
at ch.qos.logback.core.joran.GenericXMLConfigurator.doConfigure(GenericXMLConfigurator.java:170)
at ch.qos.logback.core.joran.GenericXMLConfigurator.doConfigure(GenericXMLConfigurator.java:122)
at ch.qos.logback.core.joran.GenericXMLConfigurator.doConfigure(GenericXMLConfigurator.java:65)
at ch.qos.logback.classic.util.DefaultJoranConfigurator.configureByResource(DefaultJoranConfigurator.java:68)
at ch.qos.logback.classic.util.DefaultJoranConfigurator.configure(DefaultJoranConfigurator.java:35)
at ch.qos.logback.classic.util.ContextInitializer.invokeConfigure(ContextInitializer.java:128)
at ch.qos.logback.classic.util.ContextInitializer.autoConfig(ContextInitializer.java:103)
at ch.qos.logback.classic.util.ContextInitializer.autoConfig(ContextInitializer.java:66)
at ch.qos.logback.classic.spi.LogbackServiceProvider.initializeLoggerContext(LogbackServiceProvider.java:52)
at ch.qos.logback.classic.spi.LogbackServiceProvider.initialize(LogbackServiceProvider.java:41)
at org.slf4j.LoggerFactory.bind(LoggerFactory.java:195)
at org.slf4j.LoggerFactory.performInitialization(LoggerFactory.java:182)
at org.slf4j.LoggerFactory.getProvider(LoggerFactory.java:490)
at org.slf4j.LoggerFactory.getILoggerFactory(LoggerFactory.java:476)
at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:425)
at org.apache.commons.logging.LogAdapter$Slf4jAdapter.createLocationAwareLog(LogAdapter.java:121)
at org.apache.commons.logging.LogAdapter.createLog(LogAdapter.java:95)
at org.apache.commons.logging.LogFactory.getLog(LogFactory.java:67)
at org.apache.commons.logging.LogFactory.getLog(LogFactory.java:59)
at org.springframework.boot.SpringApplication.<clinit>(SpringApplication.java:202)
at com.example.demo.DemoApplication.main(DemoApplication.java:14)
Caused by: java.lang.ClassNotFoundException: org.codehaus.janino.ScriptEvaluator
at java.base/jdk.internal.loader.BuiltinClassLoader.loadClass(BuiltinClassLoader.java:641)
at java.base/jdk.internal.loader.ClassLoaders$AppClassLoader.loadClass(ClassLoaders.java:188)
at java.base/java.lang.ClassLoader.loadClass(ClassLoader.java:520)
... 31 more
@Armstrong4444 Could you please provide a project (GitHub or attached zip) that replicates the problem?
Comment From: Armstrong4444
My sample project: https://github.com/Armstrong4444/spring-logback-config-issue-demo
I checked it out again and found out that the issue only occurrs when I set the logback config through the application.properties file. (https://github.com/Armstrong4444/spring-logback-config-issue-demo/blob/main/src/main/resources/application.properties).
When I placed the logback.xml file directly into resources inside the project it was ok. Please edit your own logback config file path in the application.properties. Thank you.
Comment From: philwebb
Sorry @Armstrong4444 but I still see the same error output with that sample when I run the application. I'm running the app from my IDE (Eclipse).
How are you running your application? Is there any other configuration that could be causing the issue?
Comment From: Armstrong4444
I added some dependencies to the gradle.build file so now the only missing dependency should be org.codehaus.janino.ScriptEvaluator. One way I simulate the issue is: 1) Build project with: ./gradlew build -x test 2) Run java program with: java -jar build\lib\demo-0.0.1-SNAPSHOT.jar
My console output is:
10:18:06,362 |-INFO in ch.qos.logback.classic.model.processor.ConfigurationModelHandlerFull - Registering a new ReconfigureOnChangeTask ReconfigureOnChangeTask(born:1703236686362)
10:18:06,362 |-INFO in ch.qos.logback.classic.model.processor.ConfigurationModelHandlerFull - Will scan for changes in [file:/C:/architektura/workspaceMain/hrp_config/logback2.xml]
10:18:06,362 |-INFO in ch.qos.logback.classic.model.processor.ConfigurationModelHandlerFull - Setting ReconfigureOnChangeTask scanning period to 30 seconds
10:18:06,377 |-INFO in ch.qos.logback.core.model.processor.StatusListenerModelHandler - Added status listener of type [ch.qos.logback.core.status.OnConsoleStatusListener]
10:18:06,443 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - Processing appender named [stdout]
10:18:06,474 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
10:18:06,693 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - Processing appender named [RollingFileTrace]
10:18:06,693 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - About to instantiate appender of type [ch.qos.logback.core.rolling.RollingFileAppender]
10:18:06,740 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy@2029780820 - No compression will be used
10:18:06,740 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy@2029780820 - Will use the pattern C:/logs/hrp-webserver-trace-%d{yyyy-MM-dd, UTC}.log for the active file
10:18:06,755 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - The date pattern is 'yyyy-MM-dd' from file name pattern 'C:/logs/hrp-webserver-trace-%d{yyyy-MM-dd, UTC}.log'.
10:18:06,755 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - Roll-over at midnight.
10:18:06,802 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - Setting initial period to 2023-12-22T09:18:06.802Z
10:18:06,802 |-INFO in ch.qos.logback.core.model.processor.ImplicitModelHandler - Assuming default type [ch.qos.logback.classic.boolex.JaninoEventEvaluator] for [evaluator] property
10:18:06,896 |-WARN in Logger[org.springframework.boot.SpringApplication] - No appenders present in context [default] for logger [org.springframework.boot.SpringApplication].
And then the exit code 1.
I checked the logback.xml file again to see if it's the same as mine, and it is. Maybe the last log message No appenders present in context [default] for logger [org.springframework.boot.SpringApplication] could be a clue? Thank you.
Comment From: wilkinsona
Thanks, @Armstrong4444, I believe I've reproduced the problem.
The logback.xml that's required to reproduce the problem is simpler than the one shared above. The following is sufficient:
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<appender name="stdout" class="ch.qos.logback.core.ConsoleAppender">
<filter class="ch.qos.logback.core.filter.EvaluatorFilter">
<evaluator>
<expression>return level <= DEBUG;</expression>
</evaluator>
<OnMismatch>DENY</OnMismatch>
<OnMatch>NEUTRAL</OnMatch>
</filter>
<encoder class="ch.qos.logback.core.encoder.LayoutWrappingEncoder">
<layout class="ch.qos.logback.contrib.json.classic.JsonLayout">
<jsonFormatter class="ch.qos.logback.contrib.jackson.JacksonJsonFormatter" />
<timestampFormat>yyyy-MM-dd'T'HH:mm:ss.SSSZ</timestampFormat>
<appendLineSeparator>true</appendLineSeparator>
</layout>
</encoder>
</appender>
<root level="INFO">
<appender-ref ref="stdout" />
</root>
</configuration>
With this file referenced through logging.config the application fails to start but logs nothing. With this file loaded through the classpath (for example, by placing it in src/main/resources), the application still fails to start but the following is logged:
Exception in thread "main" java.lang.NoClassDefFoundError: org/codehaus/janino/ScriptEvaluator
at ch.qos.logback.core.boolex.JaninoEventEvaluatorBase.start(JaninoEventEvaluatorBase.java:57)
at ch.qos.logback.core.model.processor.ImplicitModelHandler.postHandleComplex(ImplicitModelHandler.java:208)
at ch.qos.logback.core.model.processor.ImplicitModelHandler.postHandle(ImplicitModelHandler.java:186)
at ch.qos.logback.core.model.processor.DefaultProcessor.secondPhaseTraverse(DefaultProcessor.java:257)
at ch.qos.logback.core.model.processor.DefaultProcessor.secondPhaseTraverse(DefaultProcessor.java:253)
at ch.qos.logback.core.model.processor.DefaultProcessor.secondPhaseTraverse(DefaultProcessor.java:253)
at ch.qos.logback.core.model.processor.DefaultProcessor.secondPhaseTraverse(DefaultProcessor.java:253)
at ch.qos.logback.core.model.processor.DefaultProcessor.traversalLoop(DefaultProcessor.java:90)
at ch.qos.logback.core.model.processor.DefaultProcessor.process(DefaultProcessor.java:106)
at ch.qos.logback.core.joran.GenericXMLConfigurator.processModel(GenericXMLConfigurator.java:208)
at ch.qos.logback.core.joran.GenericXMLConfigurator.doConfigure(GenericXMLConfigurator.java:170)
at ch.qos.logback.core.joran.GenericXMLConfigurator.doConfigure(GenericXMLConfigurator.java:122)
at ch.qos.logback.core.joran.GenericXMLConfigurator.doConfigure(GenericXMLConfigurator.java:65)
at ch.qos.logback.classic.util.DefaultJoranConfigurator.configureByResource(DefaultJoranConfigurator.java:68)
at ch.qos.logback.classic.util.DefaultJoranConfigurator.configure(DefaultJoranConfigurator.java:35)
at ch.qos.logback.classic.util.ContextInitializer.invokeConfigure(ContextInitializer.java:122)
at ch.qos.logback.classic.util.ContextInitializer.autoConfig(ContextInitializer.java:97)
at ch.qos.logback.classic.util.ContextInitializer.autoConfig(ContextInitializer.java:65)
at ch.qos.logback.classic.spi.LogbackServiceProvider.initializeLoggerContext(LogbackServiceProvider.java:52)
at ch.qos.logback.classic.spi.LogbackServiceProvider.initialize(LogbackServiceProvider.java:41)
at org.slf4j.LoggerFactory.bind(LoggerFactory.java:195)
at org.slf4j.LoggerFactory.performInitialization(LoggerFactory.java:182)
at org.slf4j.LoggerFactory.getProvider(LoggerFactory.java:490)
at org.slf4j.LoggerFactory.getILoggerFactory(LoggerFactory.java:476)
at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:425)
at org.apache.commons.logging.LogAdapter$Slf4jAdapter.createLocationAwareLog(LogAdapter.java:121)
at org.apache.commons.logging.LogAdapter.createLog(LogAdapter.java:95)
at org.apache.commons.logging.LogFactory.getLog(LogFactory.java:67)
at org.apache.commons.logging.LogFactory.getLog(LogFactory.java:59)
at org.springframework.boot.SpringApplication.<clinit>(SpringApplication.java:191)
at com.example.demo.DemoApplication.main(DemoApplication.java:10)
Caused by: java.lang.ClassNotFoundException: org.codehaus.janino.ScriptEvaluator
at java.base/jdk.internal.loader.BuiltinClassLoader.loadClass(BuiltinClassLoader.java:641)
at java.base/jdk.internal.loader.ClassLoaders$AppClassLoader.loadClass(ClassLoaders.java:188)
at java.base/java.lang.ClassLoader.loadClass(ClassLoader.java:525)
... 31 more