Transaction already associated with request

[rakeshsagar]

Hi,

I am using teiid 8.5 and I get the error Transaction already associated with request intermittently for different queries.

The

We are using the TeiidDataSource class for creating a connection. Also, we did not set anything for setAutoCommitTxn(). This is the default i.e. AUTO.

Can you let us know the reason for this and how we can fix this problem.

The following is the stacktrace:

org.teiid.jdbc.TeiidSQLException: Transaction already associated with request.

  at org.teiid.jdbc.TeiidSQLException.create(TeiidSQLException.java:135)

  at org.teiid.jdbc.TeiidSQLException.create(TeiidSQLException.java:71)

  at org.teiid.jdbc.StatementImpl.postReceiveResults(StatementImpl.java:667)

  at org.teiid.jdbc.StatementImpl.access$100(StatementImpl.java:63)

  at org.teiid.jdbc.StatementImpl$2.onCompletion(StatementImpl.java:515)

  at org.teiid.client.util.ResultsFuture.addCompletionListener(ResultsFuture.java:148)

  at org.teiid.jdbc.StatementImpl.executeSql(StatementImpl.java:511)

  at org.teiid.jdbc.PreparedStatementImpl.executeQuery(PreparedStatementImpl.java:261)

  at com.ca.chorus.db.DbExecutor.withResultSet(DbExecutor.java:384)

  at com.ca.chorus.db.DbExecutor.gatherResults(DbExecutor.java:889)

  at com.ca.chorus.db.DbExecutor.gatherResults(DbExecutor.java:882)

  at com.ca.mfui.chorusR2.server.service.ObjectsServiceImpl.getTreeDefinitionModel(ObjectsServiceImpl.java:3234)

  at com.ca.mfui.chorusR2.server.service.ObjectsServiceImpl.getTreeForSection(ObjectsServiceImpl.java:3214)

  at com.ca.mfui.chorusR2.server.service.ObjectsServiceImpl.getTreeNodeChildren(ObjectsServiceImpl.java:3578)

  at sun.reflect.GeneratedMethodAccessor128.invoke(Unknown Source)

  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

  at java.lang.reflect.Method.invoke(Method.java:601)

  at com.ca.mfui.chorusR2.servlet.ChorusGWTServlet.processCall(ChorusGWTServlet.java:272)

  at com.google.gwt.user.server.rpc.RemoteServiceServlet.processPost(RemoteServiceServlet.java:248)

  at com.google.gwt.user.server.rpc.AbstractRemoteServiceServlet.doPost(AbstractRemoteServiceServlet.java:62)

  at javax.servlet.http.HttpServlet.service(HttpServlet.java:754)

  at javax.servlet.http.HttpServlet.service(HttpServlet.java:847)

  at com.google.inject.servlet.ServletDefinition.doService(ServletDefinition.java:263)

  at com.google.inject.servlet.ServletDefinition.service(ServletDefinition.java:178)

  at com.google.inject.servlet.ManagedServletPipeline.service(ManagedServletPipeline.java:91)

  at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:62)

  at com.google.inject.servlet.FilterDefinition.doFilter(FilterDefinition.java:168)

  at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:58)

  at com.google.inject.servlet.FilterDefinition.doFilter(FilterDefinition.java:168)

  at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:58)

  at com.google.inject.servlet.FilterDefinition.doFilter(FilterDefinition.java:168)

  at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:58)

  at com.google.inject.servlet.FilterDefinition.doFilter(FilterDefinition.java:168)

  at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:58)

  at com.ca.mfui.chorusR2.servlet.TransactionFilter$1.call(TransactionFilter.java:54)

  at com.ca.mfui.chorusR2.servlet.TransactionFilter$1.call(TransactionFilter.java:43)

  at com.ca.chorus.server.transaction.TransactionRunner.invoke(TransactionRunner.java:19)

  at com.ca.chorus.server.transaction.TransactionRunner$$EnhancerByGuice$$d14fbfd2.CGLIB$invoke$1(<generated>)

  at com.ca.chorus.server.transaction.TransactionRunner$$EnhancerByGuice$$d14fbfd2$$FastClassByGuice$$119db1fb.invoke(<generated>)

  at com.google.inject.internal.cglib.proxy.$MethodProxy.invokeSuper(MethodProxy.java:228)

  at com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:72)

  at com.ca.chorus.aop.guice.PerfTracer.trace(PerfTracer.java:75)

  at com.ca.chorus.aop.guice.PerfTracer.trace(PerfTracer.java:92)

  at com.ca.chorus.server.transaction.TransactionalMethodInterceptor.invoke(TransactionalMethodInterceptor.java:31)

  at com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:72)

  at com.google.inject.internal.InterceptorStackCallback.intercept(InterceptorStackCallback.java:52)

  at com.ca.chorus.server.transaction.TransactionRunner$$EnhancerByGuice$$d14fbfd2.invoke(<generated>)

  at com.ca.mfui.chorusR2.servlet.TransactionFilter.doFilter(TransactionFilter.java:42)

  at com.google.inject.servlet.FilterDefinition.doFilter(FilterDefinition.java:163)

  at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:58)

  at com.google.inject.servlet.FilterDefinition.doFilter(FilterDefinition.java:168)

  at com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:58)

  at com.google.inject.servlet.ManagedFilterPipeline.dispatch(ManagedFilterPipeline.java:118)

  at com.google.inject.servlet.GuiceFilter.doFilter(GuiceFilter.java:113)

  at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:246)

  at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214)

  at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:230)

  at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:149)

  at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:169)

  at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:145)

  at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:97)

  at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:102)

  at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:336)

  at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:856)

  at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:653)

  at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:920)

  at java.lang.Thread.run(Thread.java:722)

Caused by: org.teiid.core.TeiidException: Transaction already associated with request.

  at org.teiid.client.ResultsMessage.setException(ResultsMessage.java:194)

  at org.teiid.dqp.internal.process.RequestWorkItem.sendError(RequestWorkItem.java:958)

  at org.teiid.dqp.internal.process.RequestWorkItem.close(RequestWorkItem.java:543)

  at org.teiid.dqp.internal.process.RequestWorkItem.process(RequestWorkItem.java:346)

  at org.teiid.dqp.internal.process.AbstractWorkItem.run(AbstractWorkItem.java:51)

  at org.teiid.dqp.internal.process.RequestWorkItem.run(RequestWorkItem.java:248)

  at org.teiid.dqp.internal.process.DQPCore.executeRequest(DQPCore.java:307)

  at sun.reflect.GeneratedMethodAccessor95.invoke(Unknown Source)

  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

  at java.lang.reflect.Method.invoke(Method.java:601)

  at org.teiid.logging.LogManager$LoggingProxy.invoke(LogManager.java:121)

  at org.teiid.jboss.TransportService$2.invoke(TransportService.java:234)

  at $Proxy31.executeRequest(Unknown Source)

  at sun.reflect.GeneratedMethodAccessor95.invoke(Unknown Source)

  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

  at java.lang.reflect.Method.invoke(Method.java:601)

  at org.teiid.transport.LocalServerConnection$1$1.call(LocalServerConnection.java:137)

  at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)

  at java.util.concurrent.FutureTask.run(FutureTask.java:166)

  at org.teiid.dqp.internal.process.DQPWorkContext.runInContext(DQPWorkContext.java:269)

  at org.teiid.dqp.internal.process.DQPWorkContext.runInContext(DQPWorkContext.java:253)

  at org.teiid.transport.LocalServerConnection$1.invoke(LocalServerConnection.java:135)

  at $Proxy31.executeRequest(Unknown Source)

  at org.teiid.jdbc.StatementImpl.execute(StatementImpl.java:634)

  at org.teiid.jdbc.StatementImpl.executeSql(StatementImpl.java:509)

  ... 60 more

Caused by: java.lang.AssertionError: Transaction already associated with request.

  at org.teiid.core.util.Assertion.failed(Assertion.java:73)

  at org.teiid.core.util.Assertion.assertTrue(Assertion.java:68)

  at org.teiid.dqp.internal.process.Request.getTransactionContext(Request.java:321)

  at org.teiid.dqp.internal.process.Request.createProcessor(Request.java:310)

  at org.teiid.dqp.internal.process.Request.processRequest(Request.java:440)

  at org.teiid.dqp.internal.process.RequestWorkItem.processNew(RequestWorkItem.java:600)

  at org.teiid.dqp.internal.process.RequestWorkItem.process(RequestWorkItem.java:309)

  ... 81 more

Thanks

Rakesh.

[rareddy]

In your DbExecutor.java class are you properly closing the datasource's

connection after you are done?

[shawkins]

The message could be more particular.  It means that there is a request level transaction already associated with the request.  Request level transactions are associated via the session, so this could happen in circumstances a client is multi-threading requests on the same connection.  The implicit assumption of the transactional processing is that a connection will be used serially under a transaction.  If this does not describe your scenario then the logs will need to be examined more as a request scope transaction should be bound entirely to a single request.

Steve

[markaddleman]

> The implicit assumption of the transactional processing is that a connection will be used serially under a transaction

I suspect our problem is that we store the connection in the user's web session and use it across multiple HTTP requests.  This is both convenient and necessary given the session scope of temporary tables (though we might rethink this approach when we move to more recent versions of Teiid).  Under this model, it's quite possible that simultaneous requests would cause the connection to be shared across threads.  As you know, we make async Teiid requests using submiteExecute.  Currently, we mix both normal JDBC requests and these async requests.  I'm wondering if we switch entirely to the async API, would we still run into this problem?

[shawkins]

> I'm wondering if we switch entirely to the async API, would we still run into this problem?

Ideally, but that's mostly because the requirement is that asynch queries must be non-transactional.  You shouldn't see this issue with normal JDBC calls if they are running with txnAutoWrap=OFF.  A caveat with asynch is that it is possible that an asynch request may use a transaction below the request level (such as a call to a procedure with an atomic block) which could cause an issue if two asynch requests against the same session tried to use a transaction simultaneously.  This is more of a corner case internal issue though.

[markaddleman]

I understand from your comments that we are intertwining two (or more) simultaneous SQL statements on the same connection where at least statement is an INSERT/UPDATE/DELETE.  Is that right?  Moving forward, we should probably separate DML statements onto a separate connection or use some kind of read/write locking to ensure that DML statements are run exclusively. 

[shawkins]

> where at least statement is an INSERT/UPDATE/DELETE.  Is that right?

Kind of.  More than likely you have txnAutoWrap as the default of DETECT, then depending upon your transaction isolation level Teiid will attempt to wrap multiple source statements under the same transaction is a variety circumstances.  If you are just issuing a direct to source insert/update/delete - that should not need a wrapping transaction, but if it's run in conjunction with other source queries then it may need a transaction started.  If you don't care about transaction auto wrapping or will explicitly control the transaction boundary, then set txnAutoWrap to OFF.

[rakeshsagar]

Hi,

Even though there are no INSERT/UPDATE/DELETE statements in the queries being executed, we still get this error.

If we set txnAutoWrap to OFF, the SQL executes fine without the exceptions.

We have another SQL which is a View, gets blocked when executed and doesn't return the result set if we set txnAutoWrap to OFF. This SQL works fine if we set txnAutoWrap to DETECT.

So, we are in kind of a deadlock situation.

Please suggest how to resolve these issues.

Thanks

Rakesh.

[shawkins]

> Even though there are no INSERT/UPDATE/DELETE statements in the queries being executed, we still get this error.

We may think that a transaction is still needed in a variety of circumstances - especially with a higher isolation level and/or using procedures.

> If we set txnAutoWrap to OFF, the SQL executes fine without the exceptions.

Yes, that would be the expectation as we won't attempt to start a transaction for the request.

> We have another SQL which is a View, gets blocked when executed and doesn't return the result set if we set txnAutoWrap to OFF. This SQL works fine if we set txnAutoWrap to DETECT.

Have you run this by itself or is it hanging when run with other queries?  If it happens by itself, that would help narrow things down.  Presumably in DETECT mode we are starting a transaction.  From an engine perspective there is a functional difference between running under a transaction and not.  When under a transaction we will issue source commands serially and concurrently when not.  If there are custom translators with implicit assumptions of serial behavior, then there could be an issue.

[rakeshsagar]

Thanks Steve.

Yes, I have run the SQL by itself and it hangs. I have a sample JDBC program with that SQL.

Is there a way by which we can tell teiid to issue source command serially even though they are not in a transaction?

Also, can we tell the translators to execute the queries serially?

Thanks

Rakesh.

[shawkins]

> Is there a way by which we can tell teiid to issue source command serially even though they are not in a transaction?

For a global option you can set the user request source concurrency to 1.

> Also, can we tell the translators to execute the queries serially?

On a custom translator, have ExecutionFactory.isForkable return false.  Then it will have the execution processed only by the plan thread.

[rakeshsagar]

Thanks Steve.

I changed my custom translator's isForkable() to return false and the blocking issue is resolved but I do not know the reason for blocking.

I want to find the reason for the blocking and fix that as executing queries serially affects the response time of the SQL.

Can you suggest me on debugging this?

Thanks

Rakesh

[shawkins]

> Can you suggest me on debugging this?

Any state that you may be sharing between executions would be the first place to check.  You would also want a debug/trace log of the connector level events from the serial and concurrent executions to compare the sequence of events to understand better what may be causing an issue.

[rakeshsagar]

Hi Steve.

Attached the two logs for Serial Execution and Parallel Execution.

[shawkins]

Is this a custom translator using asynch logic via a data not available exception?  The parallel log shows that the engine is trying to get data at a 50ms interval.  You'll want to have your debugger attached at the time it keeps blocking to determine why it doesn't want to return data.