AOT causes Logback configuration error when using include

[michael-wirth]

Starting an application with AOT and a custom Logback configuration file (logback-spring.xml) with <include> elements can cause configuration errors (specially with file appenders).

The issue is caused by loading the serialized /META-INF/spring/logback-model and processing the model again.

By processing the model all <include> elements will load the configuration files again and attach the parsed submodules to the existing ones loaded from the serialized file.

This might not cause issues for a ConsoleAppender, but will cause a configuration error for FileAppender (same file name).

Breakpoint in ch.qos.logback.core.model.processor.IncludeModelHandler

Version

Tested with Spring Boot 3.3.1-SNAPSHOT and Java 21

Stacktrace:

java.lang.IllegalStateException: java.lang.IllegalStateException: Logback configuration error detected: 
ERROR in ch.qos.logback.core.rolling.RollingFileAppender[FILE] - 'FileNamePattern' option has the same value "/tmp/spring.log.%d{yyyy-MM-dd}.%i.gz" as that given for appender [FILE] defined earlier.
ERROR in ch.qos.logback.core.rolling.RollingFileAppender[FILE] - Collisions detected with FileAppender/RollingAppender instances defined earlier. Aborting.
ERROR in ch.qos.logback.core.rolling.RollingFileAppender[FILE] - For more information, please visit http://logback.qos.ch/codes.html#earlier_fa_collision
        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)
 

logback-spring.xml

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE configuration>
<configuration debug="false">
    <springProperty scope="context" name="application" source="spring.application.name"/>
    <include resource="org/springframework/boot/logging/logback/defaults.xml" />
    <property name="LOG_FILE" value="${LOG_FILE:-${LOG_PATH:-${LOG_TEMP:-${java.io.tmpdir:-/tmp}}}/spring.log}"/>
    <include resource="org/springframework/boot/logging/logback/console-appender.xml" />
    <include resource="org/springframework/boot/logging/logback/file-appender.xml" />

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

Reproducing the issue:

demo.zip

unzip demo.zip
cd demo
mvn package
java -jar -Dspring.aot.enabled=true target/demo-0.0.1-SNAPSHOT.jar

[mhalbritter]

This works in Boot 3.2.x. Interestingly with Boot 3.3.x, the native image built from that AOT processed application works fine. Maybe because of this?

10:37:04,857 |-WARN in ch.qos.logback.core.model.processor.IncludeModelHandler - Could not find resource corresponding to [org/springframework/boot/logging/logback/defaults.xml]
10:37:04,857 |-WARN in ch.qos.logback.core.model.processor.IncludeModelHandler - Could not find resource corresponding to [org/springframework/boot/logging/logback/file-appender.xml]

// Edit: Yup, that's it. If I generate resource hints for these files, it breaks in the same way as the AOT processed running on a JVM does.

[wilkinsona]

This looks like another consequence of the include-related changes made in Logback 1.5.5.

With Spring Boot 3.3 and Logback 1.5.5+, AOT processing of logback-spring.xml results in a serialized model that contains IncludeModel nodes. These nodes have, as sub-models, the configuration that's been read from the included XML file. When the application is started with AOT enabled, the serialized model is processed and the IncludeModel nodes are handled. The XML is processed again and the model that's read from it is added to the sub-models of the IncludeModel, alongside the existing sub-models that had already been created during AOT processing. This results in everything that was included being declared twice.

With Logback 1.4 in Spring Boot 3.2, the <include> elements are fully handled earlier on in IncludeAction while working with the XML configuration's SAX events. When the model's then being processed later, the resulting IncludeModel nodes are handled by NOPModelHandler. This avoids the double processing described above.

I've opened spring-projects/spring-aot-smoke-tests#226 so that this situation is covered by the smoke tests.