No warning is given when <springProfile> is used in a Logback <root> block

[tarasmurzenkovv]

Hi Community,

I have the following spring-logback.xml configuration

<?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"/>

    <springProperty name="appName" source="info.build.name"/>

    <springProfile name="">
        <appender name="LOGSTASH_CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
            <encoder class="net.logstash.logback.encoder.LogstashEncoder">
                <customFields>{"appName":"${appName}"}</customFields>
            </encoder>
        </appender>
        <appender name="ASYNC_LOGSTASH_CONSOLE" class="ch.qos.logback.classic.AsyncAppender">
            <queueSize>1024</queueSize>
            <discardingThreshold>0</discardingThreshold>
            <appender-ref ref="LOGSTASH_CONSOLE"/>
            <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
                <level>DEBUG</level>
            </filter>
        </appender>
    </springProfile>

    <springProfile name="sentry">
        <springProperty name="sentryDSN" source="sentry.dsn"/>
        <appender name="SENTRY" class="com.getsentry.raven.logback.SentryAppender">
            <dsn>${sentryDSN}</dsn>
            <minLevel>ERROR</minLevel>
            <ravenFactory>com.getsentry.raven.DefaultRavenFactory</ravenFactory>
        </appender>
    </springProfile>

    <root level="INFO">
        <springProfile name="docker">
            <appender-ref ref="ASYNC_LOGSTASH_CONSOLE"/>
        </springProfile>
        <springProfile name="!docker">
            <appender-ref ref="CONSOLE"/>
        </springProfile>
        <springProfile name="sentry">
            <appender-ref ref="SENTRY"/>
        </springProfile>
    </root>

</configuration>

Before upgrading to Spring Boot 3.0.0 application successfully logged to the console. However, after upgrade, it stopped doing this.

If I use this configuration

<?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"/>

    <springProperty name="appName" source="info.build.name"/>

    <springProfile name="">
        <appender name="LOGSTASH_CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
            <encoder class="net.logstash.logback.encoder.LogstashEncoder">
                <customFields>{"appName":"${appName}"}</customFields>
            </encoder>
        </appender>
        <appender name="ASYNC_LOGSTASH_CONSOLE" class="ch.qos.logback.classic.AsyncAppender">
            <queueSize>1024</queueSize>
            <discardingThreshold>0</discardingThreshold>
            <appender-ref ref="LOGSTASH_CONSOLE"/>
            <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
                <level>DEBUG</level>
            </filter>
        </appender>
    </springProfile>

    <springProfile name="sentry">
        <springProperty name="sentryDSN" source="sentry.dsn"/>
        <appender name="SENTRY" class="com.getsentry.raven.logback.SentryAppender">
            <dsn>${sentryDSN}</dsn>
            <minLevel>ERROR</minLevel>
            <ravenFactory>com.getsentry.raven.DefaultRavenFactory</ravenFactory>
        </appender>
    </springProfile>

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

</configuration>

then the app successfully logs message to the console.

[philwebb]

It's hard to say if this is a Spring Boot issue or related to the fact that Spring Boot 3.0 upgrades to Logback 1.4.x. Please could you provide a sample application as a zip file or GitHub project so that we can take a look.

[tarasmurzenkovv]

@philwebb thank you for your response. I've attached archive with the project that reproduces this behavior.
logging.zip

With only this

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

it successfully prints to the console.

With this, no output is observed

    <root level="INFO">
        <springProfile name="docker">
            <appender-ref ref="ASYNC_LOGSTASH_CONSOLE"/>
        </springProfile>
        <springProfile name="!docker">
            <appender-ref ref="CONSOLE"/>
        </springProfile>
        <springProfile name="sentry">
            <appender-ref ref="SENTRY"/>
        </springProfile>
    </root>

By saynig

related to the fact that Spring Boot 3.0 upgrades to Logback 1.4.x

could you give me the hints where it could be an issue?

[philwebb]

At first I thought that this was a bug with Logback, but I think it's actually an intentional limitation.

With the upgrade to Logback 1.4 (see #12649) in Spring Boot 3.0 we needed to refactor the way that <springProfile> works so that it now uses a ModelHandler. This makes it work in a similar way to Logback's <if> tag.

If you try and create a similar configuration to yours using <if> you'll get a much better error. For example, using a logback.xml file of:

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
	<property name="test" value="test" />
	<appender name="CONSOLE1"
		class="ch.qos.logback.core.ConsoleAppender">
		<encoder>
			<pattern>1 - %msg%n</pattern>
		</encoder>
	</appender>
	<if condition='property("test").contains("ignore")'>
		<then>
			<appender name="CONSOLE2"
				class="ch.qos.logback.core.ConsoleAppender">
				<encoder>
					<pattern>2 - %msg%n</pattern>
				</encoder>
			</appender>
		</then>
	</if>
	<root level="INFO">
		<appender-ref ref="CONSOLE1" />
		<if condition='property("test").contains("ignore")'>
			<then>
				<appender-ref ref="CONSOLE2" />
			</then>
		</if>
	</root>
</configuration>

Results in

14:37:41,297 |-WARN in IfNestedWithinSecondPhaseElementSC - <if> elements cannot be nested within an <appender>, <logger> or <root> element
14:37:41,297 |-WARN in IfNestedWithinSecondPhaseElementSC - See also http://logback.qos.ch/codes.html#nested_if_element
14:37:41,303 |-WARN in IfNestedWithinSecondPhaseElementSC - Element <root> at line 20 contains a nested <if> element at line 22

You can read more about this limitation at https://logback.qos.ch/codes.html#nested_if_element

We have the same limitation, but we don't currently have a nice SanityChecker providing details.

For your application, you can follow the advice in https://logback.qos.ch/codes.html#nested_if_element and change your config to use:

<springProfile name="docker">
	<root level="INFO">
		<appender-ref ref="ASYNC_LOGSTASH_CONSOLE" />
	</root>
</springProfile>
<springProfile name="!docker">
	<root level="INFO">
		<appender-ref ref="CONSOLE" />
	</root>
</springProfile>
<springProfile name="sentry">
	<root level="INFO">
		<appender-ref ref="SENTRY" />
	</root>
</springProfile>

[philwebb]

I'll leave this open to see if we can add a similar SanityChecker.

[tarasmurzenkovv]

Thank you for the support =)