"Connection is already associated with a different transaction" with Tomcat JDBC pool, XA ----------------------------------------------------------------------------------------- Key: JBTM-3004 URL: https://issues.jboss.org/browse/JBTM-3004 Project: JBoss Transaction Manager Issue Type: Bug Components: JTA Affects Versions: 5.next Environment: Tomcat 9.0.4, Tomcat JDBC Pool, PostgreSQL 10, Oracle JDK 8, Centos 7 x86_64 Reporter: Michal Karm Babacek Assignee: Amos Feng Priority: Critical Labels: tomcat Attachments: test.war h2. Goal To have a transaction manager taking care of XA capable data source with pooled connection to the database. h2. Means There are two pools in the Tomcat distribution, [Tomcat DBCP2|https://github.com/apache/tomcat/tree/TOMCAT_9_0_4/java/org/apache/...] and [Tomcat JDBC|https://github.com/apache/tomcat/tree/TOMCAT_9_0_4/modules/jdbc-pool...]. We choose [Tomcat JDBC|https://github.com/apache/tomcat/tree/TOMCAT_9_0_4/modules/jdbc-pool...], because [Tomcat DBCP2|https://github.com/apache/tomcat/tree/TOMCAT_9_0_4/java/org/apache/...] does not contain XA capability. XA classes, the whole [managed package from Apache Commons DBCP2|https://github.com/apache/commons-dbcp/tree/master/src/main/java/or...] is removed in the Tomcat distribution. h3. Configuration With this [simple recovery test application|https://github.com/Karm/narayana/tree/narayana-tomcat-ts/tomc...], the following is our configuration (PostgreSQL flavored): [context.xml|https://gist.github.com/Karm/0b3b06f1cd4dd359eaa0868c28c83397]. Note the disabled Arjuna connection pooling on [line 37|https://gist.github.com/Karm/0b3b06f1cd4dd359eaa0868c28c83397#file-con...] and Tomcat JDBC Pool DataSourceFactory on [line 41|https://gist.github.com/Karm/0b3b06f1cd4dd359eaa0868c28c83397#file-con...]. h3. Test The test as it is written right now works just fine except for an IllegalStateException thrown while Tomcat is being shut down, see [line 494|https://gist.github.com/Karm/6854a09b113474f5c464282bba1c706c#file-gi...]. If you [run it with PostgreSQL Docker container as described in the doc|https://github.com/Karm/narayana/tree/narayana-tomcat-ts/tomcat#3-con...] the test passes, i.e. the recovery works just fine. See the log including [database trace|https://gist.github.com/Karm/6854a09b113474f5c464282bba1c706c#file-...]. h3. Failure You can either [run the test suite|https://github.com/Karm/narayana/tree/narayana-tomcat-ts/tomcat#3-c...] or you can do it manually according to what I prepared here for you. The only expected thing is a modern Linux kernel, docker installed and this rather insecure setup in your /etc/sysconfig/docker, add: {{-H tcp://127.0.0.1:2375 -H unix:///var/run/docker.sock}} to {{OPTIONS}}. The setup script looks like this: [setup.sh|https://gist.github.com/Karm/f220076e435124f60256f29ceca9826f] Download the attached built [^test.war] to the same dir as the script. When you run the script yo should have PostgreSQL in container running and also Tomcat 9.0.4 configured and running. The first "test" is JNDI lookup and it is fine: {noformat} karm@local:~$ curl localhost:8080/test/executor/jndi -i HTTP/1.1 204 Date: Wed, 28 Mar 2018 12:35:55 GMT {noformat} Then the recovery test, when executed *once and for the first time* also passes: {noformat} karm@local:~$ curl localhost:8080/test/executor/recovery -i HTTP/1.1 204 Date: Wed, 28 Mar 2018 12:36:13 GMT {noformat} You can observe trace log on Tomcat's log and also take a look into the database trace. For the purpose of convenience in the test suite, the container as it is started right now does not log to std out, it logs into a file inside itself, see: {noformat} karm@local:~/workspaceRH/narayana-play$ docker -H=tcp://127.0.0.1:2375 exec -it narayana_db bash root@fb6e220cded5:/# tail -f /tmp/db.log 2018-03-28 12:27:23.730 UTC transaction_id:0LOG: database system was shut down at 2018-03-28 12:27:23 UTC 2018-03-28 12:27:23.742 UTC transaction_id:0LOG: database system is ready to accept connections {noformat} h4. Connection is already associated with a different transaction! When you call the app second time, it fails: {noformat} karm@local:~$ curl localhost:8080/test/executor/recovery -i HTTP/1.1 500 Content-Type: text/html;charset=utf-8 Content-Language: en Content-Length: 5725 Date: Wed, 28 Mar 2018 12:36:24 GMT Connection: close java.sql.SQLException: ARJUNA017003: Checking transaction and found that this connection is already associated with a different transaction! Obtain a new connection for this transaction. org.jboss.resteasy.core.ExceptionHandler.handleApplicationException(ExceptionHandler.java:77) org.jboss.resteasy.core.ExceptionHandler.handleException(ExceptionHandler.java:220) org.jboss.resteasy.core.SynchronousDispatcher.writeException(SynchronousDispatcher.java:175) org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:418) org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:209) org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:221) org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:56) org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:51) javax.servlet.http.HttpServlet.service(HttpServlet.java:741) org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53) </pre><p><b>Root Cause</b></p><pre>java.sql.SQLException: ARJUNA017003: Checking transaction and found that this connection is already associated with a different transaction! Obtain a new connection for this transaction. com.arjuna.ats.internal.jdbc.ConnectionImple.checkTransaction(ConnectionImple.java:1041) com.arjuna.ats.internal.jdbc.ConnectionImple.createStatement(ConnectionImple.java:153) jdk.internal.reflect.GeneratedMethodAccessor44.invoke(Unknown Source) java.base&#47;jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) java.base&#47;java.lang.reflect.Method.invoke(Method.java:564) org.apache.tomcat.jdbc.pool.ProxyConnection.invoke(ProxyConnection.java:126) org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108) org.apache.tomcat.jdbc.pool.interceptor.AbstractCreateStatementInterceptor.invoke(AbstractCreateStatementInterceptor.java:75) org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108) org.apache.tomcat.jdbc.pool.interceptor.ConnectionState.invoke(ConnectionState.java:152) org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108) org.apache.tomcat.jdbc.pool.TrapException.invoke(TrapException.java:40) org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108) org.apache.tomcat.jdbc.pool.interceptor.AbstractCreateStatementInterceptor.invoke(AbstractCreateStatementInterceptor.java:75) org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108) org.apache.tomcat.jdbc.pool.DisposableConnectionFacade.invoke(DisposableConnectionFacade.java:81) com.sun.proxy.$Proxy33.createStatement(Unknown Source) org.jboss.narayana.tomcat.jta.integration.app.TestExecutor.writeToTheDatabase(TestExecutor.java:159) org.jboss.narayana.tomcat.jta.integration.app.TestExecutor.verifyRecovery(TestExecutor.java:106) java.base&#47;jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) java.base&#47;jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) java.base&#47;jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) java.base&#47;java.lang.reflect.Method.invoke(Method.java:564) org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:139) org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:295) org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:249) org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:236) org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:402) org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:209) org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:221) org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:56) org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:51) javax.servlet.http.HttpServlet.service(HttpServlet.java:741) org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53) {noformat} One can play with the context.xml in the test.war and tweak the configuration. h3. Call to action Could you take a look at it and either help us configure the context.xml inside [^test.war] or contribute a fix for the Narayana Tomcat integration so as it could properly handle [Tomcat JDBC|https://github.com/apache/tomcat/tree/TOMCAT_9_0_4/modules/jdbc-pool... I would kindly ask you [to use my fork for the time being|https://github.com/Karm/narayana/tree/narayana-tomcat-ts/tomcat] so as we can quickly iterate. Thanks :)