Atomikos Forum

ResourceExceptions thrown ( can't find the cause )

I get the following exception when doing stress tests with JMeter , ( 5 users ) , sometimes the exception does not occur, sometimes it happens allready after a few minutes.

I can't seem the find any cause for this problem.

Some more info:
Database : SQL Server
JDBC Driver : Merlia 7.03
TransactionEssentials : 3.2.3
Hibernate : 3.2.3

Stacktrace:

com.atomikos.datasource.ResourceException: resume for XID 192.168.100.39.tm0018100086192.168.100.39.tm25 raised -2147168242: unknown com.atomikos.datasource.xa.XAResourceTransaction.resume(Unknown Source) com.atomikos.jdbc.ConnectionProxy.invoke(Unknown Source) $Proxy36.prepareStatement(Unknown Source) org.hibernate.jdbc.AbstractBatcher.getPreparedStatement(AbstractBatcher.java:505) org.hibernate.jdbc.AbstractBatcher.getPreparedStatement(AbstractBatcher.java:423) org.hibernate.jdbc.AbstractBatcher.prepareQueryStatement(AbstractBatcher.java:139) org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1547) org.hibernate.loader.Loader.doQuery(Loader.java:673) org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:236) org.hibernate.loader.Loader.doList(Loader.java:2220) org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2104) org.hibernate.loader.Loader.list(Loader.java:2099) org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:378) org.hibernate.hql.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:338) org.hibernate.engine.query.HQLQueryPlan.performList(HQLQueryPlan.java:172) org.hibernate.impl.SessionImpl.list(SessionImpl.java:1121) org.hibernate.impl.QueryImpl.list(QueryImpl.java:79) org.springframework.orm.hibernate3.HibernateTemplate$29.doInHibernate(HibernateTemplate.java:849) org.springframework.orm.hibernate3.HibernateTemplate.execute(HibernateTemplate.java:372) org.springframework.orm.hibernate3.HibernateTemplate.find(HibernateTemplate.java:840) org.springframework.orm.hibernate3.HibernateTemplate.find(HibernateTemplate.java:836)
***.***.dao.hibernate.OurDao.find(OurDao.java:80)
Dennis Baerten Send private email
Thursday, May 08, 2008
 
 
Hi,

Can you post the contents of tm.out in DEBUG mode?

Thanks
Guy
Guy Pardon Send private email
Thursday, May 08, 2008
 
 
This is the stacktrace that was thrown at that given time.

     com.atomikos.datasource.ResourceException: resume for XID 192.168.100.39.tm2018900001192.168.100.39.tm13285 raised -2147168242: unknown com.atomikos.datasource.xa.XAResourceTransaction.resume(Unknown Source) com.atomikos.jdbc.ConnectionProxy.invoke(Unknown Source) $Proxy36.prepareStatement(Unknown Source) org.hibernate.jdbc.AbstractBatcher.getPreparedStatement(AbstractBatcher.java:505) org.hibernate.jdbc.AbstractBatcher.getPreparedStatement(AbstractBatcher.java:423) org.hibernate.jdbc.AbstractBatcher.prepareQueryStatement(AbstractBatcher.java:139) org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1547) org.hibernate.loader.Loader.doQuery(Loader.java:673)
Dennis Baerten Send private email
Friday, May 09, 2008
 
 
Guy,

The following lines come from tm.out after I enabled debug logging:

08-05-08 19:25:19,515 [resin-tcp-connection-192.168.100.39:6187-37] getCompositeTransaction() returning NULL!
08-05-08 19:25:19,515 [resin-tcp-connection-192.168.100.39:6187-37] getCompositeTransaction() returning NULL!
08-05-08 19:25:19,515 [resin-tcp-connection-192.168.100.39:6187-37] Coordinator 192.168.100.39.tm2018900001 entering state: ACTIVE
08-05-08 19:25:19,515 [resin-tcp-connection-192.168.100.39:6187-37] Coordinator 192.168.100.39.tm2018900001 entered state: ACTIVE
08-05-08 19:25:19,515 [resin-tcp-connection-192.168.100.39:6187-37] (1.5) executing task: com.atomikos.timing.PooledAlarmTimer@c4dc35
08-05-08 19:25:19,515 [resin-tcp-connection-192.168.100.39:6187-37] Creating composite transaction: 192.168.100.39.tm2018900001
08-05-08 19:25:19,515 [resin-tcp-connection-192.168.100.39:6187-37] createCompositeTransaction ( 120000 ): created new ROOT transaction with id 192.168.100.39.tm2018900001
08-05-08 19:25:19,515 [resin-tcp-connection-192.168.100.39:6187-37] getCompositeTransaction()  returning instance with id 192.168.100.39.tm2018900001
08-05-08 19:25:19,515 [resin-tcp-connection-192.168.100.39:6187-37] getCompositeTransaction()  returning instance with id 192.168.100.39.tm2018900001
08-05-08 19:25:19,515 [resin-tcp-connection-192.168.100.39:6187-37] getCompositeTransaction()  returning instance with id 192.168.100.39.tm2018900001
08-05-08 19:25:19,515 [resin-tcp-connection-192.168.100.39:6187-37] Coordinator 192.168.100.39.tm2018900001 entering state: ACTIVE
08-05-08 19:25:19,515 [resin-tcp-connection-192.168.100.39:6187-37] Coordinator 192.168.100.39.tm2018900001 entered state: ACTIVE
08-05-08 19:25:19,515 [resin-tcp-connection-192.168.100.39:6187-37] JDBC ConnectionPool: using connection: ExternalXAPooledConnectionImp1210267443078com.atomikos.jdbc.ExclusiveExternalXAPooledConnectionImp@de89e9
08-05-08 19:25:19,515 [resin-tcp-connection-192.168.100.39:6187-37] getCompositeTransaction()  returning instance with id 192.168.100.39.tm2018900001
08-05-08 19:25:19,515 [resin-tcp-connection-192.168.100.39:6187-37] Coordinator 192.168.100.39.tm2018900001 entering state: ACTIVE
08-05-08 19:25:19,515 [resin-tcp-connection-192.168.100.39:6187-37] Coordinator 192.168.100.39.tm2018900001 entered state: ACTIVE
08-05-08 19:25:19,515 [resin-tcp-connection-192.168.100.39:6187-37] addParticipant ( 192.168.100.39.tm2018900001192.168.100.39.tm13285 ) for transaction 192.168.100.39.tm2018900001
08-05-08 19:25:19,515 [resin-tcp-connection-192.168.100.39:6187-37] XAResourceTransaction 192.168.100.39.tm2018900001192.168.100.39.tm13285: about to switch to XAResource com.inet.tds.ab@11ca066
08-05-08 19:25:19,515 [resin-tcp-connection-192.168.100.39:6187-37] XAResourceTransaction 192.168.100.39.tm2018900001192.168.100.39.tm13285: switched to XAResource com.inet.tds.ab@11ca066
08-05-08 19:25:19,515 [resin-tcp-connection-192.168.100.39:6187-37] getCompositeTransaction()  returning instance with id 192.168.100.39.tm2018900001
Dennis Baerten Send private email
Friday, May 09, 2008
 
 
Second part of the log :

5-08 19:25:19,515 [resin-tcp-connection-192.168.100.39:6187-37] Coordinator 192.168.100.39.tm2018900001 entering state: ACTIVE
08-05-08 19:25:19,515 [resin-tcp-connection-192.168.100.39:6187-37] Coordinator 192.168.100.39.tm2018900001 entered state: ACTIVE
08-05-08 19:25:19,515 [resin-tcp-connection-192.168.100.39:6187-37] resume for XID 192.168.100.39.tm2018900001192.168.100.39.tm13285 raised -2147168242: unknown
08-05-08 19:25:19,515 [resin-tcp-connection-192.168.100.39:6187-37] getCompositeTransaction()  returning instance with id 192.168.100.39.tm2018900001
08-05-08 19:25:19,515 [resin-tcp-connection-192.168.100.39:6187-37] getCompositeTransaction()  returning instance with id 192.168.100.39.tm2018900001
08-05-08 19:25:19,515 [resin-tcp-connection-192.168.100.39:6187-37] getCompositeTransaction()  returning instance with id 192.168.100.39.tm2018900001
08-05-08 19:25:19,515 [resin-tcp-connection-192.168.100.39:6187-37] getCompositeTransaction()  returning instance with id 192.168.100.39.tm2018900001
08-05-08 19:25:19,515 [resin-tcp-connection-192.168.100.39:6187-37] Coordinator 192.168.100.39.tm2018900001 entering state: ABORTING
08-05-08 19:25:19,515 [resin-tcp-connection-192.168.100.39:6187-37] Coordinator 192.168.100.39.tm2018900001 entered state: ABORTING
08-05-08 19:25:19,515 [resin-tcp-connection-192.168.100.39:6187-37] (1.5) executing task: com.atomikos.icatch.imp.Propagator$PropagatorThread@165076e
08-05-08 19:25:19,515 [resin-tcp-connection-192.168.100.39:6187-37] (1.5) executing task: com.atomikos.icatch.imp.Propagator$PropagatorThread@1cb060c
08-05-08 19:25:19,515 [resin-tcp-connection-192.168.100.39:6187-37] Coordinator 192.168.100.39.tm2018900001 entering state: TERMINATED
08-05-08 19:25:19,515 [resin-tcp-connection-192.168.100.39:6187-37] Coordinator 192.168.100.39.tm2018900001 : stopping timer...
08-05-08 19:25:19,515 [resin-tcp-connection-192.168.100.39:6187-37] Coordinator 192.168.100.39.tm2018900001 : disposing statehandler TERMINATED...
08-05-08 19:25:19,515 [resin-tcp-connection-192.168.100.39:6187-37] Coordinator 192.168.100.39.tm2018900001 : disposed.
08-05-08 19:25:19,515 [resin-tcp-connection-192.168.100.39:6187-37] Putting connection back in pool: ExternalXAPooledConnectionImp1210267443078com.atomikos.jdbc.ExclusiveExternalXAPooledConnectionImp@de89e9
08-05-08 19:25:19,515 [resin-tcp-connection-192.168.100.39:6187-37] getCompositeTransaction() returning NULL!
Dennis Baerten Send private email
Friday, May 09, 2008
 
 
last part of the log :

08-05-08 19:25:19,515 [resin-tcp-connection-192.168.100.39:6187-37] JDBC ConnectionProxy: delegating isClosed to connection com.inet.pool.k@1fa1136
08-05-08 19:25:19,515 [resin-tcp-connection-192.168.100.39:6187-37] getCompositeTransaction() returning NULL!
08-05-08 19:25:19,515 [resin-tcp-connection-192.168.100.39:6187-37] JDBC ConnectionProxy: delegating clearWarnings to connection com.inet.pool.k@1fa1136
08-05-08 19:25:19,515 [resin-tcp-connection-192.168.100.39:6187-37] getCompositeTransaction() returning NULL!
08-05-08 19:25:19,515 [resin-tcp-connection-192.168.100.39:6187-37] JDBC ConnectionProxy: delegating close to connection com.inet.pool.k@1fa1136
08-05-08 19:25:19,515 [resin-tcp-connection-192.168.100.39:6187-37] afterCompletion ( STATUS_ROLLEDBACK ) called  on Synchronization: org.hibernate.transaction.CacheSynchronization
08-05-08 19:25:19,515 [resin-tcp-connection-192.168.100.39:6187-37] Coordinator 192.168.100.39.tm2018900001 entered state: TERMINATED
08-05-08 19:25:19,515 [resin-tcp-connection-192.168.100.39:6187-37] rollback() done of transaction 192.168.100.39.tm2018900001
08-05-08 19:25:19,531 [resin-tcp-connection-192.168.100.39:6187-37] getCompositeTransaction() returning NULL!
08-05-08 19:25:19,531 [resin-tcp-connection-192.168.100.39:6187-37] getCompositeTransaction() returning NULL!
Dennis Baerten Send private email
Friday, May 09, 2008
 
 
Hi,

Is there anything in the DB logs?

Guy
Guy Pardon Send private email
Friday, May 09, 2008
 
 
I did not find anything in the logs of sql server, but when looking at the event viewer, there was an error of DTCProxy : "getCookie 7: The calling thread is not associated with any transaction. : -2147168242"

As you can see that number is the same as in the stacktrace.
Dennis Baerten Send private email
Tuesday, May 13, 2008
 
 
Hi,

Did you try this:

"Make sure that your SQLServer is configured for authentication: open the SQLServer Enterprise Manager ap-
plication, right-click your SQLServer and choose properties from the pop-up menu. Click the Security tab, and
make sure to select 'SQL Server and Windows' for the 'Authentication' setting."
Guy Pardon Send private email
Thursday, May 22, 2008
 
 

This topic is archived. No further replies will be accepted.

Other recent topics Other recent topics