Testing with two JPA datasources fails - possibly rolls back incorrect order

[ysb33r]

We already had:

• Test fails with two JPA datasources #28 where the recommendation was to disable automatic transaction management (with) @MicronautTest(transactional=false) and apply manual transaction management for multiple data sources that have been configured.
• Bump micronaut-jdbc-tomcat from 1.3.0 to 2.0.0 #142 which in some way is related, yet does not address testing.
• @MockBean is not always used #39 which really was a A bean with AOP advice applied cannot be replaced by another bean created with a factory micronaut-core#1740

I am coming back to this issue as I think that #28 is a very inconvenient workaround. It don't think it should be necessary to do all the extra work just because an application has more than one datasource.

To re-state the problem: When an application has more than one JPA datasource, the following exception is thrown at cleanup of the first test in the suite.

Transaction synchronization is not active
java.lang.IllegalStateException: Transaction synchronization is not active
	at io.micronaut.transaction.support.TransactionSynchronizationManager.getSynchronizations(TransactionSynchronizationManager.java:335)
	at io.micronaut.transaction.support.AbstractSynchronousTransactionManager.triggerAfterCompletion(AbstractSynchronousTransactionManager.java:1030)
	at io.micronaut.transaction.support.AbstractSynchronousTransactionManager.processRollback(AbstractSynchronousTransactionManager.java:939)
	at io.micronaut.transaction.support.AbstractSynchronousTransactionManager.rollback(AbstractSynchronousTransactionManager.java:891)
	at io.micronaut.transaction.test.DefaultTestTransactionInterceptor.rollback(DefaultTestTransactionInterceptor.java:49)
	at io.micronaut.test.extensions.AbstractMicronautExtension.rollback(AbstractMicronautExtension.java:93)
	at io.micronaut.test.extensions.spock.MicronautSpockExtension.lambda$visitSpecAnnotation$3(MicronautSpockExtension.java:107)
	at org.spockframework.runtime.extension.MethodInvocation.proceed(MethodInvocation.java:97)
	at org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecutor.runTestClass(JUnitTestClassExecutor.java:110)
	at org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecutor.execute(JUnitTestClassExecutor.java:58)
	at org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecutor.execute(JUnitTestClassExecutor.java:38)
	at org.gradle.api.internal.tasks.testing.junit.AbstractJUnitTestClassProcessor.processTestClass(AbstractJUnitTestClassProcessor.java:62)
	at org.gradle.api.internal.tasks.testing.SuiteTestClassProcessor.processTestClass(SuiteTestClassProcessor.java:51)
	at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:35)
	at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)
	at org.gradle.internal.dispatch.ContextClassLoaderDispatch.dispatch(ContextClassLoaderDispatch.java:32)
	at org.gradle.internal.dispatch.ProxyDispatchAdapter$DispatchingInvocationHandler.invoke(ProxyDispatchAdapter.java:93)
	at org.gradle.api.internal.tasks.testing.worker.TestWorker.processTestClass(TestWorker.java:118)
	at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:35)
	at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)
	at org.gradle.internal.remote.internal.hub.MessageHubBackedObjectConnection$DispatchWrapper.dispatch(MessageHubBackedObjectConnection.java:175)
	at org.gradle.internal.remote.internal.hub.MessageHubBackedObjectConnection$DispatchWrapper.dispatch(MessageHubBackedObjectConnection.java:157)
	at org.gradle.internal.remote.internal.hub.MessageHub$Handler.run(MessageHub.java:404)
	at org.gradle.internal.concurrent.ExecutorPolicy$CatchAndRecordFailures.onExecute(ExecutorPolicy.java:63)
	at org.gradle.internal.concurrent.ManagedExecutorImpl$1.run(ManagedExecutorImpl.java:46)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at org.gradle.internal.concurrent.ThreadFactoryImpl$ManagedThreadRunnable.run(ThreadFactoryImpl.java:55)
	at java.lang.Thread.run(Thread.java:748)

Let's dig into this assuming we have two datasources default and abc listed in this order in application.yml. (I explicitly chose the alphabetical reverse order as in this investigation I had no clue whether it was significant).

In my original case, the test class is annotated with MicronautTest and some tests only interacted with the default datasource, some with abc and some with both. This all turned out as non-relevant. A silly Spock setup such as 👇 produces the problem

    void 'test1'() {
        expect:
        true
    }
    void 'test2'() {
        expect:
        true
    }

test1 will fail, test2 will pass.. It cannot be bypassed by usage of something like @FailsWith or @PendingFeature, because the issue is not with the test, it is with the cleanup.

The end the logged outcome is always the same irrespective of a test failure(i.e. an assertion failure the logs) or whether test passes. In the case where the first test fails the same exception is still emitted (https://github.com/micronaut-projects/micronaut-data/blob/293560e4cdc0c56274c79c91a250925227f79784/data-tx/src/main/java/io/micronaut/transaction/support/TransactionSynchronizationManager.java#L319), but is masked by the test assertion.

The first thing was tor validate in which order the datasource are found and loaded for default and abc as the log shows.

[main] TRACE i.m.context.DefaultBeanContext - Looking up existing bean for key: @Named('default') io.micronaut.configuration.hibernate.jpa.JpaConfiguration
[main] DEBUG i.m.context.DefaultBeanContext - Resolved existing bean [io.micronaut.configuration.hibernate.jpa.JpaConfiguration@1a865273] for type [class io.micronaut.configuration.hibernate.jpa.JpaConfiguration] and qualifier [@Named('default')]
[main] TRACE i.m.context.DefaultBeanContext - Looking up existing bean for key: @Named('cm') io.micronaut.configuration.hibernate.jpa.JpaConfiguration
[main] DEBUG i.m.context.DefaultBeanContext - Resolved existing bean [io.micronaut.configuration.hibernate.jpa.JpaConfiguration@64984b0f] for type [class io.micronaut.configuration.hibernate.jpa.JpaConfiguration] and qualifier [@Named('cm')]
...
[main] TRACE i.m.context.DefaultBeanContext - Looking up existing bean for key: @Named('default') io.micronaut.configuration.hibernate.jpa.JpaConfiguration
[main] DEBUG i.m.context.DefaultBeanContext - Resolved existing bean [io.micronaut.configuration.hibernate.jpa.JpaConfiguration@61cd1c71] for type [class io.micronaut.configuration.hibernate.jpa.JpaConfiguration] and qualifier [@Named('default')]
[main] TRACE i.m.context.DefaultBeanContext - Looking up existing bean for key: @Named('abc') io.micronaut.configuration.hibernate.jpa.JpaConfiguration
[main] DEBUG i.m.context.DefaultBeanContext - Resolved existing bean [io.micronaut.configuration.hibernate.jpa.JpaConfiguration@48528634] for type [class io.micronaut.configuration.hibernate.jpa.JpaConfiguration] and qualifier [@Named(abc')]```

☝️ Ordering has been consistent, and I don't think contributes to any issue.

Next thing is the actual running of the test - the two transactions are created by the test, followed by roll back in the test cleanup.

[Test worker] DEBUG i.m.t.h.HibernateTransactionManager - Creating new transaction with name [null]: 0,-1,timeout_null
[Test worker] DEBUG i.m.t.h.HibernateTransactionManager - Opened new Session [SessionImpl(162795775<open>)] for Hibernate transaction
[Test worker] DEBUG i.m.t.h.HibernateTransactionManager - Exposing Hibernate transaction as JDBC [io.micronaut.transaction.hibernate5.HibernateTransactionManager$$Lambda$516/1081293439@4486c50a]
[Test worker] DEBUG i.m.t.h.HibernateTransactionManager - Creating new transaction with name [null]: 0,-1,timeout_null
[Test worker] DEBUG i.m.t.h.HibernateTransactionManager - Opened new Session [SessionImpl(656883468<open>)] for Hibernate transaction
[Test worker] DEBUG i.m.t.h.HibernateTransactionManager - Exposing Hibernate transaction as JDBC [io.micronaut.transaction.hibernate5.HibernateTransactionManager$$Lambda$516/1081293439@99a5bb0]
[Test worker] TRACE i.m.t.h.HibernateTransactionManager - Triggering beforeCompletion synchronization
[Test worker] DEBUG i.m.t.h.HibernateTransactionManager - Initiating transaction rollback
[Test worker] DEBUG i.m.t.h.HibernateTransactionManager - Rolling back Hibernate transaction on Session [SessionImpl(162795775<open>)]
[Test worker] TRACE i.m.t.h.HibernateTransactionManager - Triggering afterCompletion synchronization
[Test worker] DEBUG i.m.t.h.HibernateTransactionManager - Closing Hibernate Session [SessionImpl(162795775<open>)] after transaction
[Test worker] TRACE i.m.t.h.HibernateTransactionManager - Triggering beforeCompletion synchronization
[Test worker] DEBUG i.m.t.h.HibernateTransactionManager - Closing Hibernate Session [SessionImpl(656883468<open>)] after transaction
[Test worker] DEBUG i.m.t.h.HibernateTransactionManager - Resuming suspended transaction after completion of inner transaction

Notice that it creates 162795775 and then 656883468, but when it rolls back it attempts 162795775 first. I imagined that being wrong and if looking at the code here

micronaut-test/test-core/src/main/java/io/micronaut/test/extensions/AbstractMicronautExtension.java

Line 92 in 860a914

for (TestTransactionInterceptor interceptor : interceptors) {

I think the rollback should occur in reverse order for interceptors. I validated that by having a breakpoint here and then swapping the values around in the loop.

This has seemed pretty consistent after sifting through hours of logs of running tests in various combinations: When the rollback order is reversed, the first test passes; so does the rest.

I am pleading some lack of understanding the bigger picture, but what I see in front of me in my test context, is that the rollback should be in reverse order.

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[ysb33r]

Any news on this?

[alvarosanchez]

Hi @ysb33r sorry for the delay in giving you a response.

Do you have a sample application that I can use to reproduce the issue?

[picaso]

We are running into this same issue!

• Just create a sample project with multiple data sources using JPA
• Create an empty @micronatTest to force context building
• create application-test YAML pointing to the two data sources
• It will fail 100% of the time unless you specify @MicronautTest(transactional=false)

[gautamawekar]

Hi, do we have any update on this? This issue also doesn't seem to be fixed in the latest (2.*) version.
What is the official take on this? Is this not a bug and will not be fixed? Though there exists a workaround this issue needs to be fixed.

[alvarosanchez]

If anyone has a sample that reproduces the issue, we can reopen it.

[gautamawekar]

@alvarosanchez here is a reproducible test case:

https://github.com/gautamawekar/transaction-issue

[jamesdh]

I'm actually experiencing this same issue but using a single GORM datasource. First test fails every time w/ "Transaction synchronization is not active" then the rest pass, even if the test doesn't actually do anything requiring GORM/transactions.

[ebomitali]

I have the same issue with two JDBC datasources. I got test failures unless @MicronautTest(transactional=false).