I am struggling with a problem for several months now. We have worked around this problem in most cases by annotating our classes with @DirtiesContext. But the project has grown bigger and bigger and now I have reached a point in which the unit tests are starting to fail and fail again based on the order of execution. Each test class executed by itself is safe and works properly. Two testclasses after each other work properly. But I have found a strange behaviour in combination with three test-classes that breaks the context and I do not understand what is happening here.
The setup: We have declared a base-annotation that is used in most of our tests:
@AutoConfigureObservability
@ActiveProfiles(Profiles.DEVELOPMENT)
@ExtendWith(SpringExtension.class)
@SpringBootTest(webEnvironment = SpringBootTest.WebEnvironment.RANDOM_PORT,
classes = {SpringBootInitializer.class, WebAppConfig.class, DatabaseConfig.class})
@TestPropertySource(locations = {"classpath:application.properties", "classpath:application-test.properties"})
@Retention(RetentionPolicy.RUNTIME)
@Target({ElementType.TYPE})
public @interface ConsentServerTest
{}
class-1
@DisplayName("Stationary: Single applicant ID-Mercury-tests in API version 1.3")
@Slf4j
@ActiveProfiles(profiles = {Profiles.ID_MERCURY_TEST, Profiles.DEVELOPMENT})
@ConsentServerTest
public class SingleApplicantTestV1_3 extends AbstractIdMercuryTest
the ID_MERCURY_TEST profile is used to load a specific proxy-controller from our unit-tests
@Slf4j
@Profile(Profiles.ID_MERCURY_TEST)
@RestController
@RequestMapping(IdMercuryProxyController.BASE_CONTEXT_PATH)
public class IdMercuryProxyController implements FileReferences
The class AbstractIdMercuryTest is simply creating a configuration in the database with the autowired-repository-objects injected by spring. It is not defining any beans.
class-2
@ConsentServerTest
@TestPropertySource(properties = {"spring.cache.caffeine.spec=maximumSize=1000,expireAfterAccess="
+ CacheExpiresTest.CACHE_TIMEOUT_IN_SECONDS + "s"})
public class CacheExpiresTest extends Oauth2Helper
@DirtiesContext
public class Oauth2Helper {
...
@RestController
public static class ConsentUiMock
{
@GetMapping(ConsentUiMock.AUTH_RECEIVE)
public @ResponseBody String receiveAuthorizationCode(HttpServletRequest request)
{
...
}
}
@Component
public static class SpringSavedRequestFilter implements Filter
{
...
}
}
class-3
@DirtiesContext
@DisplayName("Stationary: Single applicant Panstar-tests in API version 1.3")
@Slf4j
@ActiveProfiles({"CorrelationIdTest", Profiles.DEVELOPMENT})
@ConsentServerTest
public class SingleApplicantTestV1_3 extends AbstractPanstarTest
{
...
@Profile("CorrelationIdTest")
@Component
@Order(Log4jContextClearerFilter.ORDER + 1)
public static class CorrelationIdTestFilter extends OncePerRequestFilter
{
...
}
}
If I execute the tests each for themselves everything is fine. If I execute them in the following order, the EntityManager seems broken:
But now it comes. If I change the order of the profiles of the first test like this:
@DisplayName("Stationary: Single applicant ID-Mercury-tests in API version 1.3")
@Slf4j
@ActiveProfiles(profiles = {Profiles.DEVELOPMENT, Profiles.ID_MERCURY_TEST})
@ConsentServerTest
public class SingleApplicantTestV1_3 extends AbstractIdMercuryTest
the test suddenly succeeds:
It is NOT always the entityManager that breaks. In other cases it is the CaffeineCache that has the entries not deleted anymore or the applicationContext object is being closed for some reason.
I am out of ammo here. I am not able to explain this behaviour and I it does not seem to be reproduceable in smaller projects. Any ideas on this?
Comment From: wilkinsona
Thanks for the report. Unfortunately, I think it will be hard to fully diagnose this without a reproducer.
If I change the order of the profiles of the first test […] the test suddenly succeeds
Profile ordering is significant for things like profile-specific configuration properties and their precedence. If the tests had identical configuration, changing the profile ordering of one of them may mean that it no longer reuses a cached context and uses a context of its own instead. This would also align with @DirtiesContext fixing the problem as it disables caching. That said, I'm not sure that the configuration is identical so they may not have been sharing a context anyway.
It should be possible to tell from the logs of a successful run and a failing run how many contexts were created and when they were reused. Can you share the logs for two such runs?
Comment From: Captain-P-Goldfish
I created two log-files one with a successful execution and the other one with a failed execution. But this time it even the same configuration that caused the test to fail. It also seems somewhat random that the tests are failing if the profiles-order is unchanged
execution-successful.log execution-failed.log
here the order of the tests:
FAILED
@DisplayName("Stationary: Single applicant ID-Mercury-tests in API version 1.3")
@Slf4j
@ActiveProfiles(profiles = {Profiles.ID_MERCURY_TEST, Profiles.DEVELOPMENT})
@ConsentServerTest
public class SingleApplicantTestV1_3 extends AbstractIdMercuryTest
@DisplayName("Stationary: Multiple applicants ELSTER-ID-Mercury-tests in API version 1.3")
@Slf4j
@ActiveProfiles(profiles = {Profiles.ID_MERCURY_TEST, Profiles.DEVELOPMENT})
@ConsentServerTest
public class MultipleApplicantsTestV1_3 extends AbstractElsterIdMercuryTest
FAILED
@DisplayName("Stationary: Single applicant ID-Mercury-tests in API version 1.3")
@Slf4j
@ActiveProfiles(profiles = {Profiles.ID_MERCURY_TEST, Profiles.DEVELOPMENT})
@ConsentServerTest
public class SingleApplicantTestV1_3 extends AbstractIdMercuryTest
@DisplayName("Stationary: Multiple applicants ELSTER-ID-Mercury-tests in API version 1.3")
@Slf4j
@ActiveProfiles(profiles = {Profiles.DEVELOPMENT, Profiles.ID_MERCURY_TEST})
@ConsentServerTest
public class MultipleApplicantsTestV1_3 extends AbstractElsterIdMercuryTest
SUCCESSFUL
@DisplayName("Stationary: Single applicant ID-Mercury-tests in API version 1.3")
@Slf4j
@ActiveProfiles(profiles = {Profiles.DEVELOPMENT, Profiles.ID_MERCURY_TEST})
@ConsentServerTest
public class SingleApplicantTestV1_3 extends AbstractIdMercuryTest
@DisplayName("Stationary: Multiple applicants ELSTER-ID-Mercury-tests in API version 1.3")
@Slf4j
@ActiveProfiles(profiles = {Profiles.ID_MERCURY_TEST, Profiles.DEVELOPMENT})
@ConsentServerTest
public class MultipleApplicantsTestV1_3 extends AbstractElsterIdMercuryTest
SUCCESSFUL
@DisplayName("Stationary: Single applicant ID-Mercury-tests in API version 1.3")
@Slf4j
@ActiveProfiles(profiles = {Profiles.DEVELOPMENT, Profiles.ID_MERCURY_TEST})
@ConsentServerTest
public class SingleApplicantTestV1_3 extends AbstractIdMercuryTest
@DisplayName("Stationary: Multiple applicants ELSTER-ID-Mercury-tests in API version 1.3")
@Slf4j
@ActiveProfiles(profiles = {Profiles.DEVELOPMENT, Profiles.ID_MERCURY_TEST})
@ConsentServerTest
public class MultipleApplicantsTestV1_3 extends AbstractElsterIdMercuryTest
Comment From: Captain-P-Goldfish
I just noticed, that spring-test is not entering the constructor of the class again in which the error occurs.
public StateMachineDbPersist(AppManagementStateMachineContextDao stateMachineContextRepository)
{
this.stateMachineContextRepository = stateMachineContextRepository;
}
it is entering this constructor several times but not in the moment when the third test-class is being startet. This does not suprise actually as the configuration of the first and third class are basically identical with the exception that both classes are getting additional test-beans. So I would think it is not necessary to reinstantiate. But it seems that spring loaded the wrong (a closed) context and thus the EntityManager is closed and a new transaction cannot be created. This would be my assumption. But even if this is true, I would have no idea what to do to work around it.
Comment From: Captain-P-Goldfish
My next observation:
The profile order seems only partially be relevant. It now started to fail with the following order:
@DisplayName("Stationary: Single applicant ELSTER-ID-Mercury-tests in API version 1.3")
@Slf4j
@ActiveProfiles(profiles = {Profiles.DEVELOPMENT, Profiles.ID_MERCURY_TEST})
@ConsentServerTest
public class SingleApplicantTestV1_3 extends AbstractElsterIdMercuryTest
@DisplayName("Stationary: Multiple applicants ELSTER-ID-Mercury-tests in API version 1.3")
@Slf4j
@ActiveProfiles(profiles = {Profiles.DEVELOPMENT, Profiles.ID_MERCURY_TEST})
@ConsentServerTest
public class MultipleApplicantsTestV1_3 extends AbstractElsterIdMercuryTest
but it is suddenly working with
@DisplayName("Stationary: Single applicant ELSTER-ID-Mercury-tests in API version 1.3")
@Slf4j
@ActiveProfiles(profiles = {Profiles.ID_MERCURY_TEST, Profiles.DEVELOPMENT})
@ConsentServerTest
public class SingleApplicantTestV1_3 extends AbstractElsterIdMercuryTest
@DisplayName("Stationary: Multiple applicants ELSTER-ID-Mercury-tests in API version 1.3")
@Slf4j
@ActiveProfiles(profiles = {Profiles.ID_MERCURY_TEST, Profiles.DEVELOPMENT})
@ConsentServerTest
public class MultipleApplicantsTestV1_3 extends AbstractElsterIdMercuryTest
Comment From: Captain-P-Goldfish
And one more observation:
My class OAuth2Helper is annotated with @DirtiesContext because it is adding a filter into the filter-chain as already shown above:
@DirtiesContext
public class Oauth2Helper {
...
@RestController
public static class ConsentUiMock
{
@GetMapping(ConsentUiMock.AUTH_RECEIVE)
public @ResponseBody String receiveAuthorizationCode(HttpServletRequest request)
{
...
}
}
@Component
public static class SpringSavedRequestFilter implements Filter
{
...
}
}
The class CacheExpiresTest is inheriting from this class
@ConsentServerTest
@TestPropertySource(properties = {"spring.cache.caffeine.spec=maximumSize=1000,expireAfterAccess="
+ CacheExpiresTest.CACHE_TIMEOUT_IN_SECONDS + "s"})
public class CacheExpiresTest extends Oauth2Helper
If I remove the @DirtiesContext annotation. The tests are always green no matter the order of profiles. As soon as the @DirtiesContext annotation is added again the tests start failing again, either in the first order or the other... this is pretty random.
It seems that the problem is with the @DirtiesContext.
Comment From: wilkinsona
Thanks for the logs. They seem to be for the execution of different tests.
execution-successful.log is running:
de.governikus.autent.consent.core.workflow.eid.panstar.stationary.MultipleApplicantsTestV1de.governikus.autent.consent.core.context.CacheExpiresTestde.governikus.autent.consent.core.workflow.elster.stationary.MultipleApplicantsTestV1
execution-failed.log is running:
de.governikus.autent.consent.core.workflow.eid.id_mercury.stationary.SingleApplicantTestV1_3de.governikus.autent.consent.core.context.CacheExpiresTestde.governikus.autent.consent.core.workflow.elster.stationary.MultipleApplicantsTestV1_3
Unfortunately, this means that we cannot learn anything by comparing the two logs.
What I can tell by looking at them individually is that the successful case creates three contexts – one per test class. The failed case creates two contexts - one for SingleApplicantTestV1_3 and one for CacheExpiresTest. MultipleApplicantsTestV1_3 then reuses the context created for SingleApplicantTestV1_3 and fails because the entity manager factory is closed. I cannot see any evidence that this closure is due to the context having been closed. None of the log messages that I would expect at present and DefaultTestContext also prevents the use of a closed context through an isActive() check.
I think the next thing to do here is to try and figure out why the entity manager factory has been closed and test the theory that it's not due to the context being closed. We could do that with a reproducer or you could do it using the debugger with a breakpoint on org.hibernate.internal.SessionFactoryImpl.close(). The stack trace of each call to that method for a failing run will hopefully be informative.
While looking at logs, I also noticed that you're using Spring Boot 3.1.1. While I cannot point to a specific issue, I think it would be worth upgrading to Spring Boot 3.1.5.
Comment From: Captain-P-Goldfish
Thanks for the logs. They seem to be for the execution of different tests.
execution-successful.logis running:1. `de.governikus.autent.consent.core.workflow.eid.panstar.stationary.MultipleApplicantsTestV1` 2. `de.governikus.autent.consent.core.context.CacheExpiresTest` 3. `de.governikus.autent.consent.core.workflow.elster.stationary.MultipleApplicantsTestV1`
execution-failed.logis running:1. `de.governikus.autent.consent.core.workflow.eid.id_mercury.stationary.SingleApplicantTestV1_3` 2. `de.governikus.autent.consent.core.context.CacheExpiresTest` 3. `de.governikus.autent.consent.core.workflow.elster.stationary.MultipleApplicantsTestV1_3`Unfortunately, this means that we cannot learn anything by comparing the two logs.
Sorry I also noticed this. This was a copy-paste error. I have fixed it in the upload above.
Comment From: wilkinsona
That's a very unfortunate waste of time and I can't justify spending much more time on this without you spending some time on the suggestions that I made above.
The new logs show that the tests succeed when each uses a new context. They fail when the context created for de.governikus.autent.consent.core.workflow.eid.id_mercury.stationary.SingleApplicantTestV1_3 is cached and then reused by de.governikus.autent.consent.core.workflow.elster.stationary.MultipleApplicantsTestV1_3. The cache is not being used in the success case because the profile order has changed.
I still can't see any sign of a context being closed so we still don't know why the entity manager factory has been closed. Please follow my recommendations above:
I think the next thing to do here is to try and figure out why the entity manager factory has been closed and test the theory that it's not due to the context being closed. We could do that with a reproducer or you could do it using the debugger with a breakpoint on org.hibernate.internal.SessionFactoryImpl.close(). The stack trace of each call to that method for a failing run will hopefully be informative.
While looking at logs, I also noticed that you're using Spring Boot 3.1.1. While I cannot point to a specific issue, I think it would be worth upgrading to Spring Boot 3.1.5.
Beyond this, I don't think little bits of information about your test classes is going to help I'm afraid. There are too many unknowns for them to be useful. You'll either have to provide a reproducer or follow suggestions for how you can debug the problem yourself.
Comment From: Captain-P-Goldfish
Okay I did what you asked and noticed this:
We are using a junit @TestFactory method
- The test
CacheExpiresTestwas using theEntityManagerFactory@28079which got closed after the test was finished. - The next two
DynamicTestsunderStart Workflowwere sending requests and were creatingEntityManagerswith theEntitiyManagerFactory@28401 - The following test then
Send authorization request to Consent UIis suddenly using theEntityManagerFactory@28079again and thus I am getting the error.
org.springframework.transaction.CannotCreateTransactionException: Could not open JPA EntityManager for transaction
at org.springframework.orm.jpa.JpaTransactionManager.doBegin(JpaTransactionManager.java:466)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.startTransaction(AbstractPlatformTransactionManager.java:400)
Comment From: Captain-P-Goldfish
This specific problem dissapears if I remove the @DirtiesContext annotation from the class OAuth2Helper
Comment From: wilkinsona
There's nothing that I am aware of that will change the injected entity manager factory between individual tests on the same test class so the next step would be to figure out what's doing that. I would focus on the org.springframework.orm.jpa.JpaTransactionManager instances that are involved and the entity manager factory that they have been configured with or are retrieving from the bean factory.
Comment From: Captain-P-Goldfish
Okay thanks for hearing my whining for so long. I have found the underlying issue and it is not spring-test causing it.
A part of our implementation is incompatible with the design of spring-test that an applicationContext is destroyed and an old one is reused. This is due to a static variable that is updated with the Repository-object of the new context that is being destroyed right afterwards. Then when the third test is being initiated the context is not rebuild and thus the static-variable is not updated still using the Repository-object from the closed context.
Thx for pointing me into the right direction.
Comment From: wilkinsona
Good to hear that you got to the bottom of your problem. Thanks for letting us know.