Atomikos Forum

Hello,

My testcase is a service, advised by a spring jta transaction management and atomikos as jts. The following trace is after i caught an  org.hibernate.exception.GenericJDBCException on the client - outside of the transaction bracket - calling the next service thereafter. I made sure  that the transaction in which the org.hibernate.exception.GenericJDBCException is thrown is rolled back. So, there should be no such warning when  continuing fresh with a new transaction.

22:46:07,850  WARN atomikos:107 - Attempt to create a transaction with a timeout that exceeds com.atomikos.icatch.max_timeout - truncating to: 300000
22:46:07,851  INFO atomikos:110 - createCompositeTransaction ( 3000000 ): created new ROOT transaction with id 127.0.0.2.tm0000200001
22:46:07,851  INFO Service:146 - Operation searchUsers called by main on one
22:46:07,852  INFO atomikos:110 - registerSynchronization ( com.atomikos.icatch.jta.Sync2Sync@185e155 ) for transaction 127.0.0.2.tm0000200001
22:46:07,854  WARN atomikos:107 - atomikos connection pool 'XADBMSONE': error creating proxy of connection an AtomikosXAPooledConnection with a SessionHandleState with 0 context(s)
com.atomikos.datasource.pool.CreateConnectionException: an AtomikosXAPooledConnection with a SessionHandleState with 0 context(s): connection is erroneous
    at com.atomikos.jdbc.AtomikosXAPooledConnection.testUnderlyingConnection(AtomikosXAPooledConnection.java:114)
    at com.atomikos.datasource.pool.AbstractXPooledConnection.createConnectionProxy(AbstractXPooledConnection.java:68)
    at com.atomikos.datasource.pool.ConnectionPool.borrowConnection(ConnectionPool.java:161)
    at com.atomikos.jdbc.AbstractDataSourceBean.getConnection(AbstractDataSourceBean.java:321)
    at com.atomikos.jdbc.AbstractDataSourceBean.getConnection(AbstractDataSourceBean.java:373)
    at org.hibernate.ejb.connection.InjectedDataSourceConnectionProvider.getConnection(InjectedDataSourceConnectionProvider.java:71)
    at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:446)
    at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:167)
    at org.hibernate.jdbc.AbstractBatcher.prepareQueryStatement(AbstractBatcher.java:161)
    at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1700)
    at org.hibernate.loader.Loader.doQuery(Loader.java:801)
    at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:274)
    at org.hibernate.loader.Loader.doList(Loader.java:2533)
    at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2276)
    at org.hibernate.loader.Loader.list(Loader.java:2271)
    at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:452)
    at org.hibernate.hql.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:363)
    at org.hibernate.engine.query.HQLQueryPlan.performList(HQLQueryPlan.java:196)
    at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1268)
    at org.hibernate.impl.QueryImpl.list(QueryImpl.java:102)
    at org.hibernate.ejb.QueryImpl.getResultList(QueryImpl.java:246)
    at at.itsv.playground.deployable.jta.Service.searchUsersOnDataSourceOne(Service.java:148)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:597)
    at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:309)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
    at at.itsv.playground.deployable.jta.advice.LocalRollbackOnlyHelperAdvice.invoke(LocalRollbackOnlyHelperAdvice.java:17)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:110)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
    at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:89)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
    at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
    at $Proxy16.searchUsersOnDataSourceOne(Unknown Source)
    at at.itsv.playground.container.Run.main(Run.java:149)
22:46:07,855  INFO atomikos:110 - addParticipant ( XAResourceTransaction: 3132372E302E302E322E746D30303030323030303031:3132372E302E302E322E746D32 ) for transaction 127.0.0.2.tm0000200001
22:46:07,855  INFO atomikos:110 - XAResource.start ( 3132372E302E302E322E746D30303030323030303031:3132372E302E302E322E746D32 , XAResource.TMNOFLAGS ) on resource XADBMSONE represented by XAResource instance org.apache.derby.jdbc.EmbedXAResource@1ea8dbd
22:46:07,856  INFO atomikos:110 - registerSynchronization ( com.atomikos.jdbc.AtomikosConnectionProxy$JdbcRequeueSynchronization@eb48ace8 ) for transaction 127.0.0.2.tm0000200001
22:46:07,907  INFO atomikos:110 - XAResource.end ( 3132372E302E302E322E746D30303030323030303031:3132372E302E302E322E746D32 , XAResource.TMSUCCESS ) on resource XADBMSONE represented by XAResource instance org.apache.derby.jdbc.EmbedXAResource@1ea8dbd
22:46:07,929  INFO atomikos:110 - addParticipant ( XAResourceTransaction: 3132372E302E302E322E746D30303030323030303031:3132372E302E302E322E746D32 ) for transaction 127.0.0.2.tm0000200001
22:46:07,930  INFO atomikos:110 - XAResource.start ( 3132372E302E302E322E746D30303030323030303031:3132372E302E302E322E746D32 , XAResource.TMJOIN ) on resource XADBMSONE represented by XAResource instance org.apache.derby.jdbc.EmbedXAResource@1ea8dbd
22:46:07,930  INFO atomikos:110 - registerSynchronization ( com.atomikos.jdbc.AtomikosConnectionProxy$JdbcRequeueSynchronization@eb48ace8 ) for transaction 127.0.0.2.tm0000200001
22:46:07,938  INFO atomikos:110 - XAResource.end ( 3132372E302E302E322E746D30303030323030303031:3132372E302E302E322E746D32 , XAResource.TMSUCCESS ) on resource XADBMSONE represented by XAResource instance org.apache.derby.jdbc.EmbedXAResource@1ea8dbd
22:46:07,940  INFO atomikos:110 - registerSynchronization ( com.atomikos.icatch.jta.Sync2Sync@c20893 ) for transaction 127.0.0.2.tm0000200001
22:46:07,941  INFO atomikos:110 - commit() done (by application) of transaction 127.0.0.2.tm0000200001
22:46:07,942  INFO atomikos:110 - XAResource.prepare ( 3132372E302E302E322E746D30303030323030303031:3132372E302E302E322E746D32 ) returning XAResource.XA_RDONLY on resource XADBMSONE represented by XAResource instance org.apache.derby.jdbc.EmbedXAResource@1ea8dbd
22:46:07,943  INFO atomikos:110 - afterCompletion ( STATUS_UNKNOWN ) called  on Synchronization: org.hibernate.transaction.synchronization.HibernateSynchronizationImpl@c11557
22:46:07,943  INFO atomikos:110 - afterCompletion ( STATUS_UNKNOWN ) called  on Synchronization: org.hibernate.ejb.EntityManagerImpl$1@6023f7
22:46:07,945  WARN atomikos:107 - Attempt to create a transaction with a timeout that exceeds com.atomikos.icatch.max_timeout - truncating to: 300000
22:46:07,946  INFO atomikos:110 - createCompositeTransaction ( 3000000 ): created new ROOT transaction with id 127.0.0.2.tm0000300001
22:46:07,950  INFO InnerService:61 - Operation searchUsers called by main on two
22:46:07,951  INFO atomikos:110 - registerSynchronization ( com.atomikos.icatch.jta.Sync2Sync@1bd427 ) for transaction 127.0.0.2.tm0000300001
22:46:07,959  INFO atomikos:110 - addParticipant ( XAResourceTransaction: 3132372E302E302E322E746D30303030333030303031:3132372E302E302E322E746D33 ) for transaction 127.0.0.2.tm0000300001
22:46:07,959  INFO atomikos:110 - XAResource.start ( 3132372E302E302E322E746D30303030333030303031:3132372E302E302E322E746D33 , XAResource.TMNOFLAGS ) on resource XADBMSTWO represented by XAResource instance org.apache.derby.jdbc.EmbedXAResource@a75e9f
22:46:07,960  INFO atomikos:110 - registerSynchronization ( com.atomikos.jdbc.AtomikosConnectionProxy$JdbcRequeueSynchronization@ecfd8587 ) for transaction 127.0.0.2.tm0000300001
22:46:07,970  INFO atomikos:110 - XAResource.end ( 3132372E302E302E322E746D30303030333030303031:3132372E302E302E322E746D33 , XAResource.TMSUCCESS ) on resource XADBMSTWO represented by XAResource instance org.apache.derby.jdbc.EmbedXAResource@a75e9f
22:46:07,978  INFO atomikos:110 - addParticipant ( XAResourceTransaction: 3132372E302E302E322E746D30303030333030303031:3132372E302E302E322E746D33 ) for transaction 127.0.0.2.tm0000300001
22:46:07,978  INFO atomikos:110 - XAResource.start ( 3132372E302E302E322E746D30303030333030303031:3132372E302E302E322E746D33 , XAResource.TMJOIN ) on resource XADBMSTWO represented by XAResource instance org.apache.derby.jdbc.EmbedXAResource@a75e9f
22:46:07,979  INFO atomikos:110 - registerSynchronization ( com.atomikos.jdbc.AtomikosConnectionProxy$JdbcRequeueSynchronization@ecfd8587 ) for transaction 127.0.0.2.tm0000300001
22:46:07,987  INFO atomikos:110 - XAResource.end ( 3132372E302E302E322E746D30303030333030303031:3132372E302E302E322E746D33 , XAResource.TMSUCCESS ) on resource XADBMSTWO represented by XAResource instance org.apache.derby.jdbc.EmbedXAResource@a75e9f
22:46:07,988  INFO atomikos:110 - registerSynchronization ( com.atomikos.icatch.jta.Sync2Sync@1fa10da ) for transaction 127.0.0.2.tm0000300001
22:46:07,989  INFO atomikos:110 - commit() done (by application) of transaction 127.0.0.2.tm0000300001
22:46:07,989  INFO atomikos:110 - XAResource.prepare ( 3132372E302E302E322E746D30303030333030303031:3132372E302E302E322E746D33 ) returning XAResource.XA_RDONLY on resource XADBMSTWO represented by XAResource instance org.apache.derby.jdbc.EmbedXAResource@a75e9f
22:46:07,990  INFO atomikos:110 - afterCompletion ( STATUS_UNKNOWN ) called  on Synchronization: org.hibernate.transaction.synchronization.HibernateSynchronizationImpl@688e91
22:46:07,990  INFO atomikos:110 - afterCompletion ( STATUS_UNKNOWN ) called  on Synchronization: org.hibernate.ejb.EntityManagerImpl$1@67e236

Hi,

The connection is marked as erroneous once there has been an SQLException on it. Currently, we don't test connections when they are closed (i.e. marked as available for reuse) but rather do this lazily on the next borrow...

Do you have any good reasons to justify changing this?

Thanks

Hello Guy,

The connection validation feature should already work in atomikos, using AtomikosDataSourceBean and AtomikosNonXADataSourceBean available, which are having pooling and a testQuery.

@see com.atomikos.jdbc.AbstractDataSourceBean#setTestQuery
"Sets the SQL query or statement used to validate a connection before returning it."

So if you do do this lazily on the next borrow, why do you issue a log statement on level WARN? Can i take some countermeasure against that warning, as it is good practice when logging something with level WARN?

I also do not interpret easily from the log output, if everything worked fine thereafter. Is the connection disposed and a new one generated by atomikos?

Hi,

Some warnings can't easily be avoided because they involve concurrency effects like in your case.

If this happens then the connection is indeed destroyed and removed from the pool, so later borrow requests should be fine.

HTH

Hello Guy,

Hm, but what do all that "STATUS_UNKNOWN" mean? Can you explain that status to me? I still do not understand why an errenous connection from the last transaction has (negative) effects on the next transaction! Or am i missing something?

Thx

Hi,

We currently return UNKNOWN as the status for read-only transactions, because they are by definition not committed or rolled back in the second phase of two-phase commit.

That is what it means...

HTH

Hi Guy,

Yes, thanks. Its a read-only service.

THX