Failure during test AOT processing when multiple merged context configurations result in the Logback model being written multiple times

[chicobento]

Hi,

I'm getting the following error when running ./mvnw -Dspring.aot.enabled=true test :

[ERROR] com.example.testactuatornative.Test2ITTest  Time elapsed: 0.053 s  <<< ERROR!
java.lang.IllegalStateException: Failed to load AOT ApplicationContextInitializer class for test class [com.example.testactuatornative.Test2ITTest]. This can occur if AOT processing has not taken place for the test suite. It can also occur if AOT processing failed for the test class, in which case you can consult the logs generated during AOT processing.
        at org.springframework.util.Assert.state(Assert.java:97)

This is because during ./mvnw clean test spring-boot:process-test-aot the following exception is thrown, preventing the AotTestContextInitializers from being generated for some of the IT classes:

2023-08-15T22:16:37.187Z DEBUG 2683 --- [           main] o.s.t.c.aot.TestContextAotGenerator      : Failed to generate AOT artifacts for test classes [com.example.testactuatornative.Test2ITTest]

org.springframework.test.context.aot.TestContextAotException: Failed to process test class [com.example.testactuatornative.Test2ITTest] for AOT
        at org.springframework.test.context.aot.TestContextAotGenerator.processAheadOfTime(TestContextAotGenerator.java:248)
        at org.springframework.test.context.aot.TestContextAotGenerator.lambda$processAheadOfTime$4(TestContextAotGenerator.java:206)
        at java.base/java.util.LinkedHashMap.forEach(LinkedHashMap.java:721)
        at org.springframework.util.MultiValueMapAdapter.forEach(MultiValueMapAdapter.java:179)
        at org.springframework.test.context.aot.TestContextAotGenerator.processAheadOfTime(TestContextAotGenerator.java:196)
        at org.springframework.test.context.aot.TestContextAotGenerator.processAheadOfTime(TestContextAotGenerator.java:158)
        at org.springframework.test.context.aot.TestAotProcessor.performAotProcessing(TestAotProcessor.java:91)
        at org.springframework.test.context.aot.TestAotProcessor.doProcess(TestAotProcessor.java:72)
        at org.springframework.test.context.aot.TestAotProcessor.doProcess(TestAotProcessor.java:39)
        at org.springframework.context.aot.AbstractAotProcessor.process(AbstractAotProcessor.java:82)
        at org.springframework.boot.test.context.SpringBootTestAotProcessor.main(SpringBootTestAotProcessor.java:63)
Caused by: java.lang.IllegalStateException: java.nio.file.FileAlreadyExistsException: /workspaces/test-context-spring-native/target/spring-aot/test/resources/META-INF/spring/logback-model
        at org.springframework.aot.generate.FileSystemGeneratedFiles.addFile(FileSystemGeneratedFiles.java:97)
        at org.springframework.aot.generate.GeneratedFiles.addResourceFile(GeneratedFiles.java:114)
        at org.springframework.boot.logging.logback.SpringBootJoranConfigurator$ModelWriter.writeTo(SpringBootJoranConfigurator.java:176)
        at org.springframework.boot.logging.logback.SpringBootJoranConfigurator$LogbackConfigurationAotContribution.applyTo(SpringBootJoranConfigurator.java:148)
        at org.springframework.context.aot.BeanFactoryInitializationAotContributions.applyTo(BeanFactoryInitializationAotContributions.java:78)
        at org.springframework.context.aot.ApplicationContextAotGenerator.lambda$processAheadOfTime$0(ApplicationContextAotGenerator.java:58)
        at org.springframework.context.aot.ApplicationContextAotGenerator.withCglibClassHandler(ApplicationContextAotGenerator.java:67)
        at org.springframework.context.aot.ApplicationContextAotGenerator.processAheadOfTime(ApplicationContextAotGenerator.java:53)
        at org.springframework.test.context.aot.TestContextAotGenerator.processAheadOfTime(TestContextAotGenerator.java:244)
        ... 10 common frames omitted

I have tested with fw 6.0.12-SNAPSHOT containing spring-projects/spring-framework#30861 patch but the error still occurs.

Reproducing

This issue is similar to #34337 and can be reproduced when:

• spring-cloud-context is on classpath
• logback-spring.xml is defined
• there are two ITs defining different SpringBoot properties

Minimal project example: https://github.com/chicobento/test-context-spring-native

[mhalbritter]

Can reproduce this:

2023-08-16T09:26:05.795+02:00 DEBUG 19826 --- [           main] o.s.t.c.aot.TestContextAotGenerator      : Failed to generate AOT artifacts for test classes [com.example.testactuatornative.Test2ITTest]

org.springframework.test.context.aot.TestContextAotException: Failed to process test class [com.example.testactuatornative.Test2ITTest] for AOT
        at org.springframework.test.context.aot.TestContextAotGenerator.processAheadOfTime(TestContextAotGenerator.java:248)
        at org.springframework.test.context.aot.TestContextAotGenerator.lambda$processAheadOfTime$4(TestContextAotGenerator.java:206)
        at java.base/java.util.LinkedHashMap.forEach(LinkedHashMap.java:721)
        at org.springframework.util.MultiValueMapAdapter.forEach(MultiValueMapAdapter.java:179)
        at org.springframework.test.context.aot.TestContextAotGenerator.processAheadOfTime(TestContextAotGenerator.java:196)
        at org.springframework.test.context.aot.TestContextAotGenerator.processAheadOfTime(TestContextAotGenerator.java:158)
        at org.springframework.test.context.aot.TestAotProcessor.performAotProcessing(TestAotProcessor.java:91)
        at org.springframework.test.context.aot.TestAotProcessor.doProcess(TestAotProcessor.java:72)
        at org.springframework.test.context.aot.TestAotProcessor.doProcess(TestAotProcessor.java:39)
        at org.springframework.context.aot.AbstractAotProcessor.process(AbstractAotProcessor.java:82)
        at org.springframework.boot.test.context.SpringBootTestAotProcessor.main(SpringBootTestAotProcessor.java:63)
Caused by: java.lang.IllegalStateException: java.nio.file.FileAlreadyExistsException: /Users/mkammerer/Downloads/issue-projects/sb-36997/target/spring-aot/test/resources/META-INF/spring/logback-model
        at org.springframework.aot.generate.FileSystemGeneratedFiles.addFile(FileSystemGeneratedFiles.java:97)
        at org.springframework.aot.generate.GeneratedFiles.addResourceFile(GeneratedFiles.java:114)
        at org.springframework.boot.logging.logback.SpringBootJoranConfigurator$ModelWriter.writeTo(SpringBootJoranConfigurator.java:176)
        at org.springframework.boot.logging.logback.SpringBootJoranConfigurator$LogbackConfigurationAotContribution.applyTo(SpringBootJoranConfigurator.java:148)
        at org.springframework.context.aot.BeanFactoryInitializationAotContributions.applyTo(BeanFactoryInitializationAotContributions.java:78)
        at org.springframework.context.aot.ApplicationContextAotGenerator.lambda$processAheadOfTime$0(ApplicationContextAotGenerator.java:58)
        at org.springframework.context.aot.ApplicationContextAotGenerator.withCglibClassHandler(ApplicationContextAotGenerator.java:67)
        at org.springframework.context.aot.ApplicationContextAotGenerator.processAheadOfTime(ApplicationContextAotGenerator.java:53)
        at org.springframework.test.context.aot.TestContextAotGenerator.processAheadOfTime(TestContextAotGenerator.java:244)
        ... 10 common frames omitted
Caused by: java.nio.file.FileAlreadyExistsException: /Users/mkammerer/Downloads/issue-projects/sb-36997/target/spring-aot/test/resources/META-INF/spring/logback-model
        at java.base/sun.nio.fs.UnixException.translateToIOException(UnixException.java:94)
        at java.base/sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:106)
        at java.base/sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:111)
        at java.base/sun.nio.fs.UnixFileSystemProvider.newByteChannel(UnixFileSystemProvider.java:218)
        at java.base/java.nio.file.spi.FileSystemProvider.newOutputStream(FileSystemProvider.java:484)
        at java.base/java.nio.file.Files.newOutputStream(Files.java:228)
        at java.base/java.nio.file.Files.copy(Files.java:3160)
        at org.springframework.aot.generate.FileSystemGeneratedFiles.addFile(FileSystemGeneratedFiles.java:93)
        ... 18 common frames omitted

Tested against Spring Boot 3.2.0-SNAPSHOT and Spring Cloud 2023.0.0-SNAPSHOT and it still happens.

Looks like org.springframework.boot.logging.logback.SpringBootJoranConfigurator.ModelWriter is called two times and the second time it fails because the serialized logback model is already there. This only happens when having spring cloud on the classpath.

[snicoll]

We should shield ourselves from problems like this (contributor called twice for something we expect to be present only once). Perhaps something that is missing in the core AOT api?

[chicobento]

Just a note about developer experience on this: it was tricky to track the actual problem because the TestContextAotGenerator log is debug level and the spring-boot:process-test-aot process does not fail.

So I was always getting the message

This can occur if AOT processing has not taken place for the test suite. It can also occur if AOT processing failed for the test class, in which case you can consult the logs generated during AOT processing.

And running spring-boot:process-test-aot was not helping because it completes without warnings or errors (so I had to change org.springframework.test.context logs to debug).

Perhaps this is a chance to expose the failOnError flag to the maven plugin and also increase the log level to error since the next step will fail anyways.

edit: just noticed that spring-projects/spring-framework#30977 sets the default value of failOnError to true. I have tested with 6.0.12-SNAPSHOT and have not seem this behavior being applied for this case. Perhaps I was doing something wrong here - but it worths a double check that it will work as expected and fail the mvn plugin execution

[wilkinsona]

We should shield ourselves from problems like this (contributor called twice for something we expect to be present only once)

Unfortunately, I think it's more complicated than this. When the model is generated multiple times it implies that there are multiple merged context configurations. When there are multiple merged context configurations, there may be multiple different Logback models, for example because the merged context configurations have different logging.config properties.

To avoid the failure where we try to write the resource multiple times to the same location, I think the resources will have to be namespaced somehow. This would require changes to both the code that generates the resource and the code that loads it.