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.

[wilkinsona]

I've opened spring-projects/spring-framework#31331.

[wilkinsona]

Until #31331 has been fixed, we could improve the situation by detecting whether the model that we want to write is identical to the existing file. If it is, we can skip writing it rather than failing. We'd still have to fail in situations where the models are different.

@snicoll @sbrannen do you have a feel for when spring-projects/spring-framework#31331 may be fixed? It would be useful to know as it would allow us to determine if implementing the above workaround would be a good use of time.

[snicoll]

It's not strictly related to testing but rather to mutiple context handling within the same context. This could happen if a child context had to write a file that the main one had to do as well. I have a few ideas to implement this but it might require an API change. If it does, then 6.2. I think it would be interesting to implement the workaround.

[wilkinsona]

I've already discussed this with @snicoll, but wanted to make a note here so that I don't forget.

Looking at the workaround for the Logback model writing problem. It's not straightforward unfortunately. GeneratedFiles doesn't have an API for getting existing files so we have to catch the IllegalStateException and do something like this:

private boolean duplicateModel(byte[] newModel, IllegalStateException failure) {
	if (failure.getCause() instanceof FileAlreadyExistsException faex) {
		try {
			byte[] existingModel = Files.readAllBytes(new File(faex.getFile()).toPath());
			return Arrays.equals(existingModel, newModel);
		}
		catch (IOException ex) {
			// Continue
		}
	}
	return false;
}

I'm relying on an implementation detail of FileSystemGeneratedFiles which doesn't feel great. This really shows when trying to test the workaround as TestGenerationContext and InMemoryGeneratedFiles don't behave in the same way. I could test it with a DefaultGenerationContext but that's fairly cumbersome.

Unfortunately, I think we'd need some changes to GeneratedFiles for the workaround to not be rather brittle.

[meletis]

FWIW, I managed to reproduce the issue at my repo, using the develop branch: meletis/native-build-tools-bug-report#1

There is one test class that is using an @Autowired instance of the service class and another test class that is using an @MockBean instance of the service class. The difference is what is causing the generation of two MergedContextConfiguration instances.

So, it is the same root cause, but through a different code path. I thought I should post my results here in case that changes anything in your internal prioritization system.

I would also greatly appreciate a workaround for my case, if you can think of something, since I strongly depend on the use of @MockBean during my tests.

[sbrannen]

I would also greatly appreciate a workaround for my case, if you can think of something, since I strongly depend on the use of @MockBean during my tests.

@meletis, @MockBean is not currently supported in AOT mode anyway.

• See Support Mockito with @MockBean and @SpyBean in AOT-processed tests #32195

So, if you're using Spring Boot 3.2, I suggest you look into the newly introduced @DisabledInAotMode annotation from spring-test.

[meletis]

@sbrannen , oooh! I didn't know that because I'm really new to AOT in general. Thank you very much for the guidance!

[wilkinsona]

The underlying issue in Framework is scheduled for 6.2.x. In the absence of a robust workaround, this needs to move out to Boot 3.4.