SpringBoot 'springProperty' not loaded after migration from 2.7 to 3.x

[Used Version]

3.1 (migrating from boot2.7 to 3.1)

[Problem]

The springProperty of the existing logback setting does not load the variable correctly. (and after the error below, the server will not run and will shut down.)

// logback-spring.xml
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <include resource="org/springframework/boot/logging/logback/defaults.xml"/>
    <springProperty scope="context" name="TEST_URL" source="test.url" />

    <include url="${TEST_URL}/logback/logback-remote.xml" />

    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%m%n</pattern>
            <charset>utf8</charset>
        </encoder>
    </appender>

    <root level="INFO">
        <appender-ref ref="STDOUT"/>
    </root>
</configuration>

I'm actually using a more complicated setup, but I've created an example where the problem occurs. In an empty project, the above setup works fine with boot2.7, but not with 3.x.

The error message itself says it's a formatting issue, but we can see that the springProperty above doesn't work correctly, causing TEST_URL_IS_UNDEFINED.

I'm not sure if this is the right issue to raise in spring-boot. (maybe I should go to logback.) However, I'm reporting it because I found it to be a backwards compatibility breaker in my actual project.

If this is not a bug and there is a correct way to use it, I would appreciate some guidance. Thanks.

[Stacktrace]

ERROR in ch.qos.logback.core.joran.action.IncludeAction - URL [TEST_URL_IS_UNDEFINED/logback/logback-remote.xml] is not well formed. java.net.MalformedURLException: no protocol: TEST_URL_IS_UNDEFINED/logback/logback-remote.xml
    at org.springframework.boot.logging.logback.LogbackLoggingSystem.reportConfigurationErrorsIfNecessary(LogbackLoggingSystem.java:260)
    at org.springframework.boot.logging.logback.LogbackLoggingSystem.loadConfiguration(LogbackLoggingSystem.java:247)
    at org.springframework.boot.logging.AbstractLoggingSystem.initializeWithConventions(AbstractLoggingSystem.java:80)
    at org.springframework.boot.logging.AbstractLoggingSystem.initialize(AbstractLoggingSystem.java:60)
    at org.springframework.boot.logging.logback.LogbackLoggingSystem.initialize(LogbackLoggingSystem.java:187)
    at org.springframework.boot.context.logging.LoggingApplicationListener.initializeSystem(LoggingApplicationListener.java:332)
    at org.springframework.boot.context.logging.LoggingApplicationListener.initialize(LoggingApplicationListener.java:298)
    at org.springframework.boot.context.logging.LoggingApplicationListener.onApplicationEnvironmentPreparedEvent(LoggingApplicationListener.java:246)
    at org.springframework.boot.context.logging.LoggingApplicationListener.onApplicationEvent(LoggingApplicationListener.java:223)
    at org.springframework.context.event.SimpleApplicationEventMulticaster.doInvokeListener(SimpleApplicationEventMulticaster.java:172)
    at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:165)
    at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:143)
    at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:131)
    at org.springframework.boot.context.event.EventPublishingRunListener.multicastInitialEvent(EventPublishingRunListener.java:136)
    at org.springframework.boot.context.event.EventPublishingRunListener.environmentPrepared(EventPublishingRunListener.java:81)
    at org.springframework.boot.SpringApplicationRunListeners.lambda$environmentPrepared$2(SpringApplicationRunListeners.java:64)
    at java.base/java.lang.Iterable.forEach(Iterable.java:75)
    at org.springframework.boot.SpringApplicationRunListeners.doWithListeners(SpringApplicationRunListeners.java:118)
    at org.springframework.boot.SpringApplicationRunListeners.doWithListeners(SpringApplicationRunListeners.java:112)
    at org.springframework.boot.SpringApplicationRunListeners.environmentPrepared(SpringApplicationRunListeners.java:63)
    at org.springframework.boot.SpringApplication.prepareEnvironment(SpringApplication.java:355)
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:306)
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:1305)
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:1294)
    at com.example.demo.DemoApplicationKt.main(DemoApplication.kt:13)
Exception in thread "main" java.lang.IllegalStateException: java.lang.IllegalStateException: Logback configuration error detected: 
ERROR in ch.qos.logback.core.joran.action.IncludeAction - URL [TEST_URL_IS_UNDEFINED/logback/logback-remote.xml] is not well formed. java.net.MalformedURLException: no protocol: TEST_URL_IS_UNDEFINED/logback/logback-remote.xml
    at org.springframework.boot.context.logging.LoggingApplicationListener.initializeSystem(LoggingApplicationListener.java:347)
    at org.springframework.boot.context.logging.LoggingApplicationListener.initialize(LoggingApplicationListener.java:298)
    at org.springframework.boot.context.logging.LoggingApplicationListener.onApplicationEnvironmentPreparedEvent(LoggingApplicationListener.java:246)
    at org.springframework.boot.context.logging.LoggingApplicationListener.onApplicationEvent(LoggingApplicationListener.java:223)
    at org.springframework.context.event.SimpleApplicationEventMulticaster.doInvokeListener(SimpleApplicationEventMulticaster.java:172)
    at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:165)
    at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:143)
    at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:131)
    at org.springframework.boot.context.event.EventPublishingRunListener.multicastInitialEvent(EventPublishingRunListener.java:136)
    at org.springframework.boot.context.event.EventPublishingRunListener.environmentPrepared(EventPublishingRunListener.java:81)
    at org.springframework.boot.SpringApplicationRunListeners.lambda$environmentPrepared$2(SpringApplicationRunListeners.java:64)
    at java.base/java.lang.Iterable.forEach(Iterable.java:75)
    at org.springframework.boot.SpringApplicationRunListeners.doWithListeners(SpringApplicationRunListeners.java:118)
    at org.springframework.boot.SpringApplicationRunListeners.doWithListeners(SpringApplicationRunListeners.java:112)
    at org.springframework.boot.SpringApplicationRunListeners.environmentPrepared(SpringApplicationRunListeners.java:63)
    at org.springframework.boot.SpringApplication.prepareEnvironment(SpringApplication.java:355)
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:306)
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:1305)
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:1294)
    at com.example.demo.DemoApplicationKt.main(DemoApplication.kt:13)
Caused by: java.lang.IllegalStateException: Logback configuration error detected: 
ERROR in ch.qos.logback.core.joran.action.IncludeAction - URL [TEST_URL_IS_UNDEFINED/logback/logback-remote.xml] is not well formed. java.net.MalformedURLException: no protocol: TEST_URL_IS_UNDEFINED/logback/logback-remote.xml
    at org.springframework.boot.logging.logback.LogbackLoggingSystem.reportConfigurationErrorsIfNecessary(LogbackLoggingSystem.java:260)
    at org.springframework.boot.logging.logback.LogbackLoggingSystem.loadConfiguration(LogbackLoggingSystem.java:247)
    at org.springframework.boot.logging.AbstractLoggingSystem.initializeWithConventions(AbstractLoggingSystem.java:80)
    at org.springframework.boot.logging.AbstractLoggingSystem.initialize(AbstractLoggingSystem.java:60)
    at org.springframework.boot.logging.logback.LogbackLoggingSystem.initialize(LogbackLoggingSystem.java:187)
    at org.springframework.boot.context.logging.LoggingApplicationListener.initializeSystem(LoggingApplicationListener.java:332)
    ... 19 more

Comment From: geminiKim

Add something interesting. Although springProperty is not imported in the include tag. But it seems to be imported in normal syntax.

[application.yml]

test.url: http://test.url

[logback-spring.xml]

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <include resource="org/springframework/boot/logging/logback/defaults.xml"/>
    <springProperty scope="context" name="TEST_URL" source="test.url" />

<!--    <include url="${TEST_URL}/logback/logback-remote.xml" />-->

    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>${TEST_URL} | %m%n</pattern>
            <charset>utf8</charset>
        </encoder>
    </appender>

    <root level="INFO">
        <appender-ref ref="STDOUT"/>
    </root>
</configuration>

[Application Log]

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::                (v3.1.0)

http://test.url | Starting DemoApplicationKt using Java 17.0.2 with PID 41983 
http://test.url | The following 1 profile is active: "dev"
http://test.url | Tomcat initialized with port(s): 8080 (http)
http://test.url | Starting service [Tomcat]
http://test.url | Starting Servlet engine: [Apache Tomcat/10.1.8]
http://test.url | Initializing Spring embedded WebApplicationContext
http://test.url | Root WebApplicationContext: initialization completed in 358 ms
http://test.url | Tomcat started on port(s): 8080 (http) with context path ''
http://test.url | Started DemoApplicationKt in 0.701 seconds (process running for 0.892)

${TEST_URL} works in pattern tag

Comment From: geminiKim

I figured out that this problem is related to the point when the logback.xml file is read. Also, I verified that it could be solved in relation to the modification of SpringPropertyAction and raised a PR. Please review it, thank you.

Comment From: philwebb

Thanks for the PR, but I don't think we should make the change that you're suggesting as it is setting the result as a side-effect of parsing the XML. With Logback 1.4, the general pattern is to have an Action class that is called by the XML parser to create a Model and a ModelHandler to actually do the work.

I think that the reason things no longer work for you is due to changes in Logback itself. The following configuration also fails in the same way but will work with Logback 1.2:

<configuration>
    <variable scope="context" name="includedUrl" value="file:included.xml" />
    <include url="${includedUrl}"/>
</configuration>

To me this looks like Logback issue LOGBACK-1731, so you might want to comment and subscribe to that issue.

Comment From: LiYing2010

hi dear team We encounter the same issue, and I like to share some investigation result

We upgraded from old version: SpringBoot 2.7.6 + SpringFramework 5.3.24 + logback 1.2.11 to latest version SpringBoot 3.2.0 + SpringFramework 6.1.2 + logback 1.4.14

and the same error occurs.

Our log configuration file logback-spring.xml is:

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <springProperty scope="context" name="spring_active_profile" source="spring.profiles.active" />
    <include resource="logback-${spring_active_profile}.xml" />
</configuration>

what we trying to do is simple, include dedicated logback-foo.xml for each active spring profile e.g. logback-local.xml for local profile, logback-beta.xml for beta profile, logback-real.xml for real profile, etc

this configuration worked fine in the old version SpringBoot 2.7.6 + SpringFramework 5.3.24 + logback 1.2.11

but in the latest version, the same error occurs, and the log of logback is:

17:29:17,738 |-WARN in ch.qos.logback.core.joran.action.IncludeAction - Could not find resource corresponding to [logback-spring_active_profile_IS_UNDEFINED.xml]

means, spring_active_profile defined in the springProperty, can not be resolved

the following is our investigation result:

(1) SpringPropertyAction (in SpringBoot) is executed it create a SpringPropertyModel instance

(2) IncludeAction (in Logback) is executed it try to substitute the "resource" value "logback-${spring_active_profile}.xml" but failed, the result is "logback-spring_active_profile_IS_UNDEFINED.xml" that's why IncludeAction failed to find and load the correct logback-foo.xml file

(3) SpringPropertyModelHandler (in SpringBoot) is executed it read the spring.profiles.active value, and put it into CONTEXT

I think the cause of this issue is not about Logback issue LOGBACK-1731, but about the execution order

(2) IncludeAction (in Logback) is executed BEFORE (3) SpringPropertyModelHandler so property value defined in springProperty tag get no chance to be set to the correct scope when IncludeAction try to use it

I read a little of Logback source code: https://github.com/qos-ch/logback/blob/bd11e72017941331f2c3ba5101429359aced5a47/logback-core/src/main/java/ch/qos/logback/core/joran/GenericXMLConfigurator.java#L164-L170

        Model top = buildModelFromSaxEventList(recorder.getSaxEventList());    <-- this part will parse XML file and execute all the FooAction for each tag
        if (top == null) {
            addError(ErrorCodes.EMPTY_MODEL_STACK);
            return;
        }
        sanityCheck(top);
        processModel(top);    <-- this part will executed all the Model Handlers

look like this execution order is difficult to change so maybe it should be fixed at Springboot side, by doing (3) inside (1) just like the idea of PR #35670

how do you think?

Comment From: philwebb

so maybe it should be fixed at Springboot side, by doing (3) inside (1) just like the idea of PR https://github.com/spring-projects/spring-boot/pull/35670

@LiYing2010 I think it's unlikely that we'd want to make any change similar to #35670 for the same reason we declined it last time. It doesn't look like LOGBACK-1731 has been fixed yet, so I think we should wait for that.

Comment From: LiYing2010

@philwebb

thank you very much for replying

I will wait for LOGBACK-1731