Hello,
I am a Java developer and I have found an issue with the SpringBoot 3.0.4 framework in the org.springframework.boot.logging.logback.LogbackLoggingSystem class, specifically on line 280.
The current code is as follows:
private void stopAndReset(LoggerContext loggerContext) {
loggerContext.stop();
loggerContext.reset();
if (isBridgeHandlerInstalled()) {
addLevelChangePropagator(loggerContext);
}
}
I would like to suggest a modification to this method:
private void stopAndReset(LoggerContext loggerContext) {
loggerContext.stop();
loggerContext.reset();
// FIXME: At this point, all initial default states (including appenders and filters) of loggerContext have been cleared.
// If other loggers are still printing logs (such as org.springframework.jndi.JndiTemplate which reads environment variable values from <springProperty scope="context" ...>),
// a warning noAppenderDefinedWarning will be issued, causing StatusPrinter.printInCaseOfErrorsOrWarnings(loggerContext) to be executed.
// This will ultimately result in a large amount of unimportant logs being printed before SpringBoot completes startup.
loggerContext.getTurboFilterList().add(FILTER);
if (isBridgeHandlerInstalled()) {
addLevelChangePropagator(loggerContext);
}
}
I hope this suggestion is helpful. Thank you for your work on this open source software.
Best regards,
Toby
Comment From: philwebb
Thanks for the suggestion, but I'm not sure we can add the FILTER at this point and be sure that it will be removed again later. Do you have a sample application you can share that triggers the noAppenderDefinedWarning in the way you're describing?
Comment From: naivetoby
Hi @philwebb I created a really simple app that replicates the problem.
Running the sample app generates those log messages on startup.
01:07:56,786 |-INFO in ch.qos.logback.classic.LoggerContext[default] - This is logback-classic version 1.4.5
01:07:56,802 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
01:07:56,802 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.xml]
01:07:56,803 |-INFO in ch.qos.logback.classic.BasicConfigurator@66ce957f - Setting up default configuration.
01:07:57,229 |-WARN in Logger[org.springframework.jndi.JndiTemplate] - No appenders present in context [default] for logger [org.springframework.jndi.JndiTemplate].
01:07:57,233 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - Processing appender named [consoleAppender]
01:07:57,233 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
01:07:57,235 |-INFO in ch.qos.logback.core.model.processor.ImplicitModelHandler - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
01:07:57,245 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - Processing appender named [dailyRollingFileAppender]
01:07:57,245 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - About to instantiate appender of type [ch.qos.logback.core.rolling.RollingFileAppender]
Comment From: naivetoby
Hi @philwebb I created a anthor really simple app that replicates the problem too.
Running the sample app generates those log messages on startup.
01:47:15,368 |-INFO in ch.qos.logback.classic.LoggerContext[default] - This is logback-classic version 1.4.5
01:47:15,380 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
01:47:15,380 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.xml]
01:47:15,381 |-INFO in ch.qos.logback.classic.BasicConfigurator@60a2630a - Setting up default configuration.
01:47:15,712 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - Processing appender named [consoleAppender]
01:47:15,712 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - About to instantiate appender of type [com.example.demo.DemoConsoleAppender]
01:47:15,714 |-INFO in ch.qos.logback.core.model.processor.ImplicitModelHandler - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
01:47:15,723 |-WARN in Logger[com.example.demo.DemoConsoleAppender] - No appenders present in context [default] for logger [com.example.demo.DemoConsoleAppender].
01:47:15,723 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - Processing appender named [dailyRollingFileAppender]
01:47:15,723 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - About to instantiate appender of type [ch.qos.logback.core.rolling.RollingFileAppender]
Comment From: eu-rlarsen
And just to add to this, I also get a lot of INFO logs, and one WARN for "org.springframework.boot.context.properties.source.ConfigurationPropertySourcesPropertyResolver$DefaultResolver"
I don't have an app that I have made for this test, I just think the issue is the same as for the "org.springframework.jndi.JndiTemplate"
```17:46:14,736 |-INFO in ch.qos.logback.core.joran.util.ConfigurationWatchListUtil@3b90a30a - Adding [jar:file:/Users/Shared/.m2/repository/org/springframework/boot/spring-boot/3.0.4/spring-boot-3.0.4.jar!/org/springframework/boot/logging/logback/defaults.xml] to configuration watch list. 17:46:14,736 |-INFO in ch.qos.logback.core.joran.spi.ConfigurationWatchList@299270eb - URL [jar:file:/Users/Shared/.m2/repository/org/springframework/boot/spring-boot/3.0.4/spring-boot-3.0.4.jar!/org/springframework/boot/logging/logback/defaults.xml] is not of type file 17:46:14,738 |-INFO in ch.qos.logback.core.joran.action.ConversionRuleAction - registering conversion word clr with class [org.springframework.boot.logging.logback.ColorConverter] 17:46:14,738 |-INFO in ch.qos.logback.core.joran.action.ConversionRuleAction - registering conversion word wex with class [org.springframework.boot.logging.logback.WhitespaceThrowableProxyConverter] 17:46:14,738 |-INFO in ch.qos.logback.core.joran.action.ConversionRuleAction - registering conversion word wEx with class [org.springframework.boot.logging.logback.ExtendedWhitespaceThrowableProxyConverter] 17:46:14,744 |-WARN in Logger[org.springframework.boot.context.properties.source.ConfigurationPropertySourcesPropertyResolver$DefaultResolver] - No appenders present in context [default] for logger [org.springframework.boot.context.properties.source.ConfigurationPropertySourcesPropertyResolver$DefaultResolver]. 17:46:14,744 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [org.apache.catalina.startup.DigesterFactory] to ERROR 17:46:14,744 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@69fa8e76 - Propagating ERROR level on Logger[org.apache.catalina.startup.DigesterFactory] onto the JUL framework 17:46:14,744 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [org.apache.catalina.util.LifecycleBase] to ERROR 17:46:14,744 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@69fa8e76 - Propagating ERROR level on Logger[org.apache.catalina.util.LifecycleBase] onto the JUL framework 17:46:14,745 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [org.apache.coyote.http11.Http11NioProtocol] to WARN 17:46:14,745 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@69fa8e76 - Propagating WARN level on Logger[org.apache.coyote.http11.Http11NioProtocol] onto the JUL framework 17:46:14,745 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [org.apache.sshd.common.util.SecurityUtils] to WARN 17:46:14,745 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@69fa8e76 - Propagating WARN level on Logger[org.apache.sshd.common.util.SecurityUtils] onto the JUL framework 17:46:14,745 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [org.apache.tomcat.util.net.NioSelectorPool] to WARN 17:46:14,745 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@69fa8e76 - Propagating WARN level on Logger[org.apache.tomcat.util.net.NioSelectorPool] onto the JUL framework 17:46:14,745 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [org.eclipse.jetty.util.component.AbstractLifeCycle] to ERROR 17:46:14,745 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@69fa8e76 - Propagating ERROR level on Logger[org.eclipse.jetty.util.component.AbstractLifeCycle] onto the JUL framework 17:46:14,745 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [org.hibernate.validator.internal.util.Version] to WARN 17:46:14,745 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@69fa8e76 - Propagating WARN level on Logger[org.hibernate.validator.internal.util.Version] onto the JUL framework 17:46:14,745 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [org.springframework.boot.actuate.endpoint.jmx] to WARN 17:46:14,745 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@69fa8e76 - Propagating WARN level on Logger[org.springframework.boot.actuate.endpoint.jmx] onto the JUL framework 17:46:14,745 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [ch.qos.logback] to WARN 17:46:14,745 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@69fa8e76 - Propagating WARN level on Logger[ch.qos.logback] onto the JUL framework 17:46:14,745 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [com.codehale] to WARN 17:46:14,745 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@69fa8e76 - Propagating WARN level on Logger[com.codehale] onto the JUL framework 17:46:14,745 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [com.netflix] to WARN 17:46:14,745 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@69fa8e76 - Propagating WARN level on Logger[com.netflix] onto the JUL framework 17:46:14,745 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [com.sun.xml] to WARN 17:46:14,745 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@69fa8e76 - Propagating WARN level on Logger[com.sun.xml] onto the JUL framework 17:46:14,745 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [com.sun.xml.internal.ws] to WARN 17:46:14,745 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@69fa8e76 - Propagating WARN level on Logger[com.sun.xml.internal.ws] onto the JUL framework 17:46:14,745 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [javax.xml.bind] to WARN 17:46:14,745 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@69fa8e76 - Propagating WARN level on Logger[javax.xml.bind] onto the JUL framework 17:46:14,745 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [jndi] to WARN 17:46:14,745 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@69fa8e76 - Propagating WARN level on Logger[jndi] onto the JUL framework 17:46:14,745 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [net.snowflake.client.jdbc.SnowflakeLoggedFeatureNotSupportedException] to ERROR 17:46:14,745 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@69fa8e76 - Propagating ERROR level on Logger[net.snowflake.client.jdbc.SnowflakeLoggedFeatureNotSupportedException] onto the JUL framework 17:46:14,745 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [org.apache] to WARN 17:46:14,745 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@69fa8e76 - Propagating WARN level on Logger[org.apache] onto the JUL framework 17:46:14,745 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [org.apache.hive] to INFO 17:46:14,745 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@69fa8e76 - Propagating INFO level on Logger[org.apache.hive] onto the JUL framework 17:46:14,745 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [org.apache.kafka.clients.consumer.ConsumerConfig] to ERROR 17:46:14,745 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@69fa8e76 - Propagating ERROR level on Logger[org.apache.kafka.clients.consumer.ConsumerConfig] onto the JUL framework 17:46:14,745 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [org.eclipse] to WARN 17:46:14,745 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@69fa8e76 - Propagating WARN level on Logger[org.eclipse] onto the JUL framework 17:46:14,745 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [org.hibernate] to WARN 17:46:14,745 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@69fa8e76 - Propagating WARN level on Logger[org.hibernate] onto the JUL framework 17:46:14,745 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [org.hibernate.engine.internal.StatisticalLoggingSessionEventListener] to INFO 17:46:14,745 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@69fa8e76 - Propagating INFO level on Logger[org.hibernate.engine.internal.StatisticalLoggingSessionEventListener] onto the JUL framework 17:46:14,745 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [org.springframework] to INFO 17:46:14,745 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@69fa8e76 - Propagating INFO level on Logger[org.springframework] onto the JUL framework 17:46:14,745 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [org.springframework.web] to INFO 17:46:14,745 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@69fa8e76 - Propagating INFO level on Logger[org.springframework.web] onto the JUL framework 17:46:14,745 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [springfox] to WARN 17:46:14,745 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@69fa8e76 - Propagating WARN level on Logger[springfox] onto the JUL framework 17:46:14,745 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [org.springframework.boot.autoconfigure.security.AuthenticationManagerConfiguration] to ERROR 17:46:14,745 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@69fa8e76 - Propagating ERROR level on Logger[org.springframework.boot.autoconfigure.security.AuthenticationManagerConfiguration] onto the JUL framework 17:46:14,745 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [org.springframework.boot.autoconfigure.security.reactive.ReactiveUserDetailsServiceAutoConfiguration] to ERROR 17:46:14,745 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@69fa8e76 - Propagating ERROR level on Logger[org.springframework.boot.autoconfigure.security.reactive.ReactiveUserDetailsServiceAutoConfiguration] onto the JUL framework 17:46:14,745 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [org.springframework.boot.autoconfigure.security.servlet.UserDetailsServiceAutoConfiguration] to ERROR 17:46:14,745 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@69fa8e76 - Propagating ERROR level on Logger[org.springframework.boot.autoconfigure.security.servlet.UserDetailsServiceAutoConfiguration] onto the JUL framework 17:46:14,745 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - Processing appender named [CONSOLE] 17:46:14,745 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender] 17:46:14,746 |-INFO in ch.qos.logback.classic.model.processor.RootLoggerModelHandler - Setting level of ROOT logger to INFO 17:46:14,746 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@69fa8e76 - Propagating INFO level on Logger[ROOT] onto the JUL framework 17:46:14,746 |-INFO in ch.qos.logback.core.model.processor.AppenderRefModelHandler - Attaching appender named [CONSOLE] to Logger[ROOT] 17:46:14,746 |-INFO in ch.qos.logback.core.model.processor.DefaultProcessor@bdd2027 - End of configuration. 17:46:14,746 |-INFO in org.springframework.boot.logging.logback.SpringBootJoranConfigurator@31f20c9f - Registering current configuration as safe fallback point
Comment From: chicobento
Hi, we are facing the same issue. Im having it triggered by the same codepath as @eu-rlarsen.
Do you have a sample application you can share that triggers the
noAppenderDefinedWarningin the way you're describing?
@philwebb , in our case, it is being triggered by the following log line:
14:33:03,891 |-WARN in Logger[org.springframework.boot.context.properties.source.ConfigurationPropertySourcesPropertyResolver$DefaultResolver] - No appenders present in context [default] for logger [org.springframework.boot.context.properties.source.ConfigurationPropertySourcesPropertyResolver$DefaultResolver].
Which is triggered by this code PropertySourcesPropertyResolver.logKeyFound.
Steps to reproduce: Create a new webmvc app on initializr.
logback-spring.xml
<configuration>
<springProperty scope="context" name="APP_NAME" source="spring.application.name" />
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%-5level ${APP_NAME} %logger{36} - %msg%n</pattern>
</encoder>
</appender>
<root level="INFO">
<appender-ref ref="STDOUT" />
</root>
</configuration>
application.properties
# define a SERVICE_NAME env var to reproduce. Without SERVICE_NAME env it runs fine
spring.application.name=${SERVICE_NAME:my-service}
Define a env variable SERVICE_NAME=myapp and run the main method.
Some findings
It is not reproducible on 2.7.9, so it looks like something that was introduced on 3.x.
The PropertySourcesPropertyResolver.logKeyFound is triggered in the same way on 2.7.x and 3.0.x, so it is not the cause of the problem.
I noticed that on 3.x the logback's ch.qos.logback.core.util.StatusPrinter.printInCaseOfErrorsOrWarnings method is called twice, while on 2.7.x it is called only once - before the 'warnings' generated by the PropertySourcesPropertyResolver.logKeyFound method call were added to the StatusManager.
The additional call to the printInCaseOfErrorsOrWarnings is triggered by LoggingApplicationListener.initializeSystem:332
edit: adding the stack of the call that is triggering the print errors issue
Comment From: matf
We're also using <springProperty> in our logback configuration and are being hit by this issue.
While I wasn't yet able to pinpoint the exact cause, the following configuration element will suppress all logback status messages until this issue is fixed. Maybe it helps someone else stumbling over this issue.
<configuration>
<statusListener class="ch.qos.logback.core.status.NopStatusListener" />
...
Obviously, this will also hide any actual configuration issues your configuration might contain, so use with care. You could also implement your own status listener that does not fully suppress the output.
Comment From: rPraml
We are facing the same issue:
as @chicobento already stated, the code that applies the system properties is executed twice. First time in LoggingApplicationListener.initialize
and then again in Line 298 initializeSystem which does a reinitialize later in the stack
LogBackLoggingSystem.reinitialize:
@Override
protected void reinitialize(LoggingInitializationContext initializationContext) {
getLoggerContext().reset(); // removes all appenders
getLoggerContext().getStatusManager().clear();
loadConfiguration(initializationContext, getSelfInitializationConfig(), null);
}
@Override
protected void loadConfiguration(LoggingInitializationContext initializationContext, String location,
LogFile logFile) {
if (initializationContext != null) {
applySystemProperties(initializationContext.getEnvironment(), logFile); // effectively calls apply the second time
}
...
}
protected void apply(LogFile logFile, PropertyResolver resolver) {
setSystemProperty(resolver, EXCEPTION_CONVERSION_WORD, "logging.exception-conversion-word");
setSystemProperty(PID_KEY, new ApplicationPid().toString());
setSystemProperty(resolver, CONSOLE_LOG_PATTERN, "logging.pattern.console"); // <--- this line calls logKeyFound, but no appenders are present in this run
...
}
Possible fix the code
if (initializationContext != null) {
applySystemProperties(initializationContext.getEnvironment(), logFile);
}
must not be called after the getLoggerContext().reset(); so, move this from loadConfiguration to reinitialize or either move the getLoggerContext().reset(); & getLoggerContext().getStatusManager().clear(); to the loadConfiguration method.
The breaking change was possibly introduced with https://github.com/spring-projects/spring-boot/commit/3980c5af486343062b401f6bb3874cf880c73efd#diff-791625700b5f37dfa8f4e174ed25f81a353260de13287ac720d9cac682667361 (It is not part of the 2.7.x branch)
Comment From: wilkinsona
There's a window where the deny-all turbo filter has been removed but Logback has not yet been configured. If any logging that would have reached an appender is performed in this window, the unwanted status messages will be logged. This window can be closed by ensuring that the turbo filter is in place. This is similar to the suggestion above but it needs to be done in such a way that we can be certain that the filter will be removed again.
Comment From: 4braincells
I am just migrating from 2.7.18 to 3.3.1 and experiencing this behaviour. Shouldn't this have been fixed?
Connected to the target VM, address: '127.0.0.1:51316', transport: 'socket'
16:41:25,940 |-INFO in ch.qos.logback.classic.LoggerContext[default] - This is logback-classic version 1.5.6
16:41:25,941 |-INFO in ch.qos.logback.classic.util.ContextInitializer@4b672daa - Here is a list of configurators discovered as a service, by rank:
16:41:25,941 |-INFO in ch.qos.logback.classic.util.ContextInitializer@4b672daa - org.springframework.boot.logging.logback.RootLogLevelConfigurator
16:41:25,941 |-INFO in ch.qos.logback.classic.util.ContextInitializer@4b672daa - They will be invoked in order until ExecutionStatus.DO_NOT_INVOKE_NEXT_IF_ANY is returned.
16:41:25,942 |-INFO in ch.qos.logback.classic.util.ContextInitializer@4b672daa - Constructed configurator of type class org.springframework.boot.logging.logback.RootLogLevelConfigurator
16:41:25,948 |-INFO in ch.qos.logback.classic.util.ContextInitializer@4b672daa - org.springframework.boot.logging.logback.RootLogLevelConfigurator.configure() call lasted 1 milliseconds. ExecutionStatus=INVOKE_NEXT_IF_ANY
16:41:25,948 |-INFO in ch.qos.logback.classic.util.ContextInitializer@4b672daa - Trying to configure with ch.qos.logback.classic.joran.SerializedModelConfigurator
16:41:25,948 |-INFO in ch.qos.logback.classic.util.ContextInitializer@4b672daa - Constructed configurator of type class ch.qos.logback.classic.joran.SerializedModelConfigurator
16:41:25,950 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.scmo]
16:41:25,950 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.scmo]
16:41:25,950 |-INFO in ch.qos.logback.classic.util.ContextInitializer@4b672daa - ch.qos.logback.classic.joran.SerializedModelConfigurator.configure() call lasted 2 milliseconds. ExecutionStatus=INVOKE_NEXT_IF_ANY
16:41:25,950 |-INFO in ch.qos.logback.classic.util.ContextInitializer@4b672daa - Trying to configure with ch.qos.logback.classic.util.DefaultJoranConfigurator
16:41:25,950 |-INFO in ch.qos.logback.classic.util.ContextInitializer@4b672daa - Constructed configurator of type class ch.qos.logback.classic.util.DefaultJoranConfigurator
16:41:25,950 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
16:41:25,951 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.xml]
16:41:25,951 |-INFO in ch.qos.logback.classic.util.ContextInitializer@4b672daa - ch.qos.logback.classic.util.DefaultJoranConfigurator.configure() call lasted 1 milliseconds. ExecutionStatus=INVOKE_NEXT_IF_ANY
16:41:25,951 |-INFO in ch.qos.logback.classic.util.ContextInitializer@4b672daa - Trying to configure with ch.qos.logback.classic.BasicConfigurator
16:41:25,951 |-INFO in ch.qos.logback.classic.util.ContextInitializer@4b672daa - Constructed configurator of type class ch.qos.logback.classic.BasicConfigurator
16:41:25,951 |-INFO in ch.qos.logback.classic.BasicConfigurator@ea9b7c6 - Setting up default configuration.
16:41:25,964 |-INFO in ch.qos.logback.classic.util.ContextInitializer@4b672daa - ch.qos.logback.classic.BasicConfigurator.configure() call lasted 13 milliseconds. ExecutionStatus=NEUTRAL
...
Comment From: wilkinsona
Yes, we believe it has been fixed. You may want to check the output for a WARN level message that's reporting a problem with your Logback configuration. If that doesn't help and you would like us to investigate, please open a new issue with a minimal example that reproduces the unwanted logging and we can take a look.
Comment From: 4braincells
Of course I have WARNings,
11:12:27,582 |-WARN in ch.qos.logback.core.model.processor.AppenderModelHandler - Appender named [APPLICATION] not referenced. Skipping further processing.
11:12:27,582 |-WARN in ch.qos.logback.core.model.processor.AppenderModelHandler - Appender named [SERVER] not referenced. Skipping further processing.
11:12:27,582 |-WARN in ch.qos.logback.core.model.processor.AppenderModelHandler - Appender named [MISSING-MESSAGES] not referenced. Skipping further processing.
etc.
because I am using only logback-spring.xml with 2 springProfiles inside:
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<contextListener class="ch.qos.logback.classic.jul.LevelChangePropagator">
<resetJUL>true</resetJUL>
</contextListener>
<springProperty scope="context" name="LOG_PATH" source="logging.file.path"/>
<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%d [%thread] %highlight(%-5level) %cyan(%logger{15}) %msg %n</pattern>
</encoder>
</appender>
<appender name="APPLICATION" class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>${LOG_PATH}/Console.log</file>
<rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
<fileNamePattern>${LOG_PATH}/archived/Console.%d{yyyy-MM-dd}.log-%i.gz</fileNamePattern>
<maxFileSize>2GB</maxFileSize>
<totalSizeCap>20GB</totalSizeCap>
<maxHistory>40</maxHistory>
<cleanHistoryOnStart>true</cleanHistoryOnStart>
</rollingPolicy>
<encoder>
<pattern>%d [%thread] %-5level %logger{15} %msg %n</pattern>
</encoder>
</appender>
<appender name="SERVER" class="ch.qos.logback.core.rolling.RollingFileAppender">
.. </appender>
<appender name="MISSING-MESSAGES" class="ch.qos.logback.core.rolling.RollingFileAppender">
.. </appender>
<appender name="REQUEST-RESPONSE" class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>${LOG_PATH}/RequestResponse.log</file>
<rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
<fileNamePattern>${LOG_PATH}/archived/RequestResponse.%d{yyyy-MM-dd}.log-%i.gz</fileNamePattern>
<maxFileSize>100MB</maxFileSize>
<totalSizeCap>1GB</totalSizeCap>
<maxHistory>40</maxHistory>
<cleanHistoryOnStart>true</cleanHistoryOnStart>
</rollingPolicy>
<encoder>
<pattern>%d [%thread] %-5level %logger{15} %msg %n</pattern>
</encoder>
</appender>
<appender name="TRANSACTIONS" class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>${LOG_PATH}/Transactions.log</file>
<rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
<fileNamePattern>${LOG_PATH}/archived/Transactions.%d{yyyy-MM-dd}.log-%i.gz</fileNamePattern>
<maxFileSize>100MB</maxFileSize>
<totalSizeCap>1GB</totalSizeCap>
<maxHistory>40</maxHistory>
<cleanHistoryOnStart>true</cleanHistoryOnStart>
</rollingPolicy>
<encoder>
<pattern>%d %-5level %msg %n</pattern>
</encoder>
</appender>
etc.
<springProfile name="develop">
<logger name="org.springframework" level="INFO"/>
<logger name="org.hibernate" level="WARN"/>
<logger name="org.springframework" level="WARN"/>
<logger name="com.zaxxer.hikari" level="WARN"/>
<logger name="de.fourbraincells" level="INFO"/>
<logger name="de.fourbraincells.simpleOnlineRegistration.util.DBMessageSource" level="DEBUG"/>
<root level="INFO">
<appender-ref ref="CONSOLE"/>
</root>
</springProfile>
<springProfile name="production">
<logger name="org.hibernate" level="WARN">
<appender-ref ref="SERVER"/>
</logger>
<logger name="org.springframework" level="WARN">
<appender-ref ref="SERVER"/>
</logger>
<logger name="com.zaxxer.hikari" level="WARN">
<appender-ref ref="SERVER"/>
</logger>
<logger name="org.springframework.data" level="WARN">
<appender-ref ref="SERVER"/>
</logger>
<logger name="de.fourbraincells.simpleOnlineRegistration.controller.SorErrorController" level="ERROR">
<appender-ref ref="ACCESS-ERROR"/>
</logger>
<logger name="de.fourbraincells.simpleOnlineRegistration.util.DBMessageSource" level="DEBUG">
<appender-ref ref="MISSING-MESSAGES"/>
</logger>
<logger name="de.fourbraincells.simpleOnlineRegistration.service.log.AccessLogService" level="INFO">
<appender-ref ref="ACCESS"/>
</logger>
<logger name="de.fourbraincells.simpleOnlineRegistration.service.log.MailLogService" level="INFO">
<appender-ref ref="MAIL"/>
</logger>
<logger name="de.fourbraincells.simpleOnlineRegistration.service.log.LogService" level="INFO">
<appender-ref ref="TRANSACTIONS"/>
</logger>
<logger name="de.fourbraincells.simpleOnlineRegistration.configuration.IPAddressInterceptor" level="INFO">
<appender-ref ref="REQUEST-RESPONSE"/>
</logger>
<logger name="de.fourbraincells.simpleOnlineRegistration.configuration.RequestResponseLoggingInterceptor"
level="INFO">
<appender-ref ref="REQUEST-RESPONSE"/>
</logger>
<root level="INFO">
<appender-ref ref="APPLICATION"/>
</root>
</springProfile>
</configuration>
Comment From: wilkinsona
@4braincells, that's a different problem to the one that this issue fixed.
It's Logback's standard behaviour to log a warning when an appender is declared but is not used. In that situation, it also logs all of its info messages to provide more context for the problem. I think you could fix the problem by declaring the <appender> within the <springProfile> where it's used. If you have an appender that's used in multiple profiles, you could declare it in a new <springProfile name="profileOne | profileTwo"> section.
If you have any further questions, please follow up on Stack Overflow. As mentioned in the guidelines for contributing, we prefer to use GitHub issues only for bugs and enhancements.
Comment From: 4braincells
Thanks. This really helped.
The warning behaviour is known to me. But there were no warnings for unused appenders in spring boot before V3. So this is new. I didnt find anything in the logback docs though.
regarding steak-overflow, I am still struggling against them, they dont let me login using github nor google ID. It has been your decision to to there, I dont like stackoverflow, and you didnt ask me LOL