SpringBoot Unnecessary log outputs during application start with logback(-spring.xml)

Hi!

We are currently upgrading applications from Spring Boot 2.7.x to Spring Boot 3. We use (default) logback as our logging framework. We configure logging using a logback-spring.xml to add a custom layout to log in a JSON format for production use.

After upgrading the first application, we suddenly noticed strange log messages from logback during application startup, which did not occur with Spring Boot 2.7.x. The messages look roughly like this:

17:34:44,541 |-INFO in ch.qos.logback.classic.LoggerContext[default] - This is logback-classic version 1.4.11
17:34:44,543 |-INFO in ch.qos.logback.classic.util.ContextInitializer@53fd0d10 - Here is a list of configurators discovered as a service, by rank:
17:34:44,543 |-INFO in ch.qos.logback.classic.util.ContextInitializer@53fd0d10 -   org.springframework.boot.logging.logback.RootLogLevelConfigurator
17:34:44,543 |-INFO in ch.qos.logback.classic.util.ContextInitializer@53fd0d10 - They will be invoked in order until ExecutionStatus.DO_NOT_INVOKE_NEXT_IF_ANY is returned.
17:34:44,543 |-INFO in ch.qos.logback.classic.util.ContextInitializer@53fd0d10 - Constructed configurator of type class org.springframework.boot.logging.logback.RootLogLevelConfigurator
17:34:44,552 |-INFO in ch.qos.logback.classic.util.ContextInitializer@53fd0d10 - org.springframework.boot.logging.logback.RootLogLevelConfigurator.configure() call lasted 1 milliseconds. ExecutionStatus=INVOKE_NEXT_IF_ANY
17:34:44,552 |-INFO in ch.qos.logback.classic.util.ContextInitializer@53fd0d10 - Trying to configure with ch.qos.logback.classic.joran.SerializedModelConfigurator
17:34:44,552 |-INFO in ch.qos.logback.classic.util.ContextInitializer@53fd0d10 - Constructed configurator of type class ch.qos.logback.classic.joran.SerializedModelConfigurator
17:34:44,559 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.scmo]
17:34:44,560 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.scmo]
17:34:44,560 |-INFO in ch.qos.logback.classic.util.ContextInitializer@53fd0d10 - ch.qos.logback.classic.joran.SerializedModelConfigurator.configure() call lasted 8 milliseconds. ExecutionStatus=INVOKE_NEXT_IF_ANY
17:34:44,560 |-INFO in ch.qos.logback.classic.util.ContextInitializer@53fd0d10 - Trying to configure with ch.qos.logback.classic.util.DefaultJoranConfigurator
17:34:44,560 |-INFO in ch.qos.logback.classic.util.ContextInitializer@53fd0d10 - Constructed configurator of type class ch.qos.logback.classic.util.DefaultJoranConfigurator
...

When we searched the issue tracker, we came across the following existing issue from March 2023, which seems to be similar in nature, which is https://github.com/spring-projects/spring-boot/issues/34505.

A user describes there that the following setting can be used as a workaround to suppress the unwanted logging, even if this could also suppress other possibly desired messages (https://github.com/spring-projects/spring-boot/issues/34505#issuecomment-1679195874):

<statusListener class="ch.qos.logback.core.status.NopStatusListener" />

I have created a minimal Spring Boot application with which one can reproduce the effect.

https://github.com/msievers/spring-boot-logback-issue

If you change the spring-boot-starter-parent from 3.1.3 to 2.7.14, the unnecessary logging disappears.

If I can provide any further information please let me know.

Best regards,

Michael

Comment From: wilkinsona

This is Logback's standard behavior when it has been misconfigured. Towards the end of the messages, you'll see two WARN-level messages telling you what the problem is:

17:44:29,504 |-WARN in ch.qos.logback.core.model.processor.AppenderModelHandler - Appender named [CONSOLE] not referenced. Skipping further processing.
17:44:29,504 |-WARN in ch.qos.logback.core.model.processor.AppenderModelHandler - Appender named [MY_CONSOLE_APPENDER] not referenced. Skipping further processing.

You can fix the problem by referencing the appenders:

    <root level="INFO">
        <appender-ref ref="CONSOLE"/>
        <appender-ref ref="MY_CONSOLE_APPENDER"/>
    </root>

Comment From: msievers

Thank you @wilkinsona for pointing this out.

Just for the records or anybody who stumbles over this later on ...

With Spring Boot 2.7.x our logack-spring.xml was like this without seeing any further messages from logback:

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <include resource="org/springframework/boot/logging/logback/defaults.xml"/>
    <include resource="org/springframework/boot/logging/logback/console-appender.xml"/>

    <appender name="CONSOLE_JSON" class="ch.qos.logback.core.ConsoleAppender">
        <encoder class="ch.qos.logback.core.encoder.LayoutWrappingEncoder">
            <layout class="my.custom.JsonLayout" />
        </encoder>
    </appender>

    <springProfile name="production">
        <root level="INFO">
            <appender-ref ref="CONSOLE_JSON"/>
        </root>
    </springProfile>

    <springProfile name="!production">
        <root level="INFO">
            <appender-ref ref="CONSOLE"/>
        </root>
    </springProfile>
</configuration>

Starting with Spring Boot 3 we moved things into the springProfile guarded sections and changed it to be like:

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <include resource="org/springframework/boot/logging/logback/defaults.xml"/>

    <springProfile name="production">
        <appender name="CONSOLE_JSON" class="ch.qos.logback.core.ConsoleAppender">
            <encoder class="ch.qos.logback.core.encoder.LayoutWrappingEncoder">
                <layout class="my.custom.JsonLayout" />
            </encoder>
        </appender>
        <root level="INFO">
            <appender-ref ref="CONSOLE_JSON"/>
        </root>
    </springProfile>

    <springProfile name="!production">
        <include resource="org/springframework/boot/logging/logback/console-appender.xml"/>
        <root level="INFO">
            <appender-ref ref="CONSOLE"/>
        </root>
    </springProfile>
</configuration>

because else we would get WARN messages from logback on startup that either one or the other appender is not used.

Comment From: davebarda

@wilkinsona , I have the same issues, I don't see other workaround as for duplicating the configuration and duplicating the configuration. Any idea?

Comment From: wilkinsona

No, sorry. The reason for the change in behavior due to this change that's in Logback 1.3 and later. You many want to ask the Logback community for some advice.