<springProperty> and <springProfile> do not work in <include> after Logback upgrade

[fupgang]

Logback refactored the inclusion of configuration snippets in version 1.5.5. (For details see this commit and this comment in logback repo.)
Updating logback from <= 1.5.4 to >= 1.5.5 breaks <springProperty> when used within an included configuration snippet.

Example

A simple spring boot application using logback.
A prefix for log messages is configured in the environment using <springProperty>.

logback.xml

<configuration>
    <include resource="included.xml" optional="false" />
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>${prefix} %msg %n</pattern>
        </encoder>
    </appender>
    <root level="DEBUG">
        <appender-ref ref="STDOUT" />
    </root>
</configuration>

included.xml

<included>
    <!-- works with 1.5.4, broken with 1.5.5 and 1.5.6 -->
    <springProperty name="prefix" source="prefix" scope="context" defalultValue="[default prefix]" />
</included>

in application.properties

prefix = [prefix from env]

The expected log output is "[prefix from env] ..." but acutaly is "prefix_IS_UNDEFINED ...".

Cause

Since the refactoring a new instance of JoranConfigurator is created when an inclusion is processed.

new code in JoranConfigurator

    private JoranConfigurator makeAnotherInstance() {
        JoranConfigurator jc = new JoranConfigurator();
        jc.setContext(this.context);
        return jc;
    }

    public void buildModelInterpretationContext() {
        super.buildModelInterpretationContext();
        this.modelInterpretationContext.setConfiguratorSupplier(() -> {
            return this.makeAnotherInstance();
        });
    }

The new instance is currently not a SpringBootJoranConfigurator but a simple JoranConfigurator that does not know about springs extensions (e.g. <springProperty>).
Therefore <springProfile> might be affected as well.

Fix

Overriding buildModelInterpretationContext() in SpringBootJoranConfigurator to provide an instance of SpringBootJoranConfigurator with the same LoggingInitializationContext.

[fupgang]

The bug affects 3.3.0-RC1 that uses logback 1.5.6 (see #40401).

Spring boot 3.2.5 uses version 1.4.14 of logback, the issue arises when manually upgrade to logback >= 1.5.5.

[mhalbritter]

Hey, thanks for the report. Can you please attach your sample project as something we can clone or unzip? Thanks!

[fupgang]

logback-bug-demo.tar.gz

[scottfrederick]

Thanks for the sample @fupgang.

The Spring Boot documentation states that a file logback-spring.xml should be used to configure Logback instead of logback.xml when Spring extensions are used. That doesn't fix the problem, but the correct file name should be used once this issue is resolved.

Spring Boot adds the springProperty extension rule using the path configuration/springProperty:

spring-boot/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/logging/logback/SpringBootJoranConfigurator.java

Lines 103 to 108 in d534204

	public void addElementSelectorAndActionAssociations(RuleStore ruleStore) {
	super.addElementSelectorAndActionAssociations(ruleStore);
	ruleStore.addRule(new ElementSelector("configuration/springProperty"), SpringPropertyAction::new);
	ruleStore.addRule(new ElementSelector("*/springProfile"), SpringProfileAction::new);
	ruleStore.addTransparentPathPart("springProfile");
	}

Logback's SimpleRuleStore.matchActions(ElementPath elementPath) will be called when the springProperty element is encountered in included.xml using the provided sample.

When using Logback 1.5.4 and earlier, matchActions gets a path [configuration][springProperty], the lookup succeeds, and the prefix property is resolved.

When using Logback 1.5.5 and later, matchActions gets a path [included][springProperty], the lookup fails, and the prefix property is not resolved.

Spring Boot might be able to address this by adding springProperty with a path like */springProperty as we do with springProfile.

@ceki Was this change in lookup paths intended as part of the changes mentioned above in Logback 1.5.5 and 1.5.6?

[ceki]

@scottfrederick I think the analysis provided by @fupgang is quite accurate.

The key phrase is:

Since the refactoring a new instance of JoranConfigurator is created when an inclusion is processed.

IncludeModelHandler (new in logback 1.5.5) reads the included XML file and transforms it to a model using a new configurator instance provided by a supplier set in ModelInterpretationContext.

The fix suggested by @fupgang seems quite appropriate. Indeed, the default configurator supplier will return an instance of JoranConfigurator instead of SpringBootJoranConfigurator. JoranConfigurator is unaware of <springProperty>.

As for the matchActions, IncludeModelHandler adds a mapping replacing "includes" path-part with "configuration" path-part which should be fine as well.

In short, overriding buildModelInterpretationContext in SpringBootJoranConfigurator is the way to go.

Perhaps something like:

 class SpringBootJoranConfigurator extends JoranConfigurator  {

    private SpringBootJoranConfigurator makeAnotherSpringBootConfiguratorInstance() {
        SpringBootJoranConfigurator sbjc = new SpringBootJoranConfigurator();
        sbjc.setContext(this.context);
        return sbjc;
    }

    public void buildModelInterpretationContext() {
        super.buildModelInterpretationContext();
        this.modelInterpretationContext.setConfiguratorSupplier(() -> {
            return this.makeAnotherSpringBootConfiguratorInstance();
        });
    }