Atomikos Forum

Ok this issue is a followup of

default82df.html?community.6.289.0

I got this exception again when upgrading from spring-2.5.3 to spring-2.5.6 . I am using atomikos transactionEssentials-3.5.3 and hibernate-3.3.1.GA. Using MYSQL database.

NOTE THAT: I DON'T GET THE FOLLOWING EXCEPTION WHEN USING SPRING-2.5.3. I GET THIS EXCEPTION FOR ALL SPRING VERSIONS HIGHER THAN SPRING-2.5.3

Exception:

[TESTPROJECT] ERROR [http-8080-Processor24] [testweb].invoke(253) | Servlet.service() for servlet testweb threw exception
com.atomikos.datasource.ResourceException: XA resource 'XA-CORE-TESTPROJECT-DATASOURCE': resume for XID '3139322E3136382E302E322E746D30303332383030303331:3139322E3136382E302E322E746D333233' raised -5: invalid arguments were given for the XA operation
    at com.atomikos.datasource.xa.XAResourceTransaction.resume(XAResourceTransaction.java:653)
    at com.atomikos.datasource.xa.session.BranchEnlistedStateHandler.<init>(BranchEnlistedStateHandler.java:32)
    at com.atomikos.datasource.xa.session.NotInBranchStateHandler.checkEnlistBeforeUse(NotInBranchStateHandler.java:41)
    at com.atomikos.datasource.xa.session.TransactionContext.checkEnlistBeforeUse(TransactionContext.java:60)
    at com.atomikos.datasource.xa.session.SessionHandleState.notifyBeforeUse(SessionHandleState.java:151)
    at com.atomikos.jdbc.AtomikosConnectionProxy.enlist(AtomikosConnectionProxy.java:165)
    at com.atomikos.jdbc.AtomikosConnectionProxy.invoke(AtomikosConnectionProxy.java:105)
    at $Proxy1.prepareStatement(Unknown Source)
    at org.hibernate.jdbc.AbstractBatcher.getPreparedStatement(AbstractBatcher.java:534)
    at org.hibernate.jdbc.AbstractBatcher.getPreparedStatement(AbstractBatcher.java:452)
    at org.hibernate.jdbc.AbstractBatcher.prepareQueryStatement(AbstractBatcher.java:161)
    at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1573)
    at org.hibernate.loader.Loader.doQuery(Loader.java:696)
    at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:259)
    at org.hibernate.loader.Loader.loadCollection(Loader.java:2015)
    at org.hibernate.loader.collection.CollectionLoader.initialize(CollectionLoader.java:59)
    at org.hibernate.persister.collection.AbstractCollectionPersister.initialize(AbstractCollectionPersister.java:587)
    at org.hibernate.event.def.DefaultInitializeCollectionEventListener.onInitializeCollection(DefaultInitializeCollectionEventListener.java:83)
    at org.hibernate.impl.SessionImpl.initializeCollection(SessionImpl.java:1743)
    at org.hibernate.collection.AbstractPersistentCollection.initialize(AbstractPersistentCollection.java:366)
    at org.hibernate.collection.AbstractPersistentCollection.read(AbstractPersistentCollection.java:108)
    at org.hibernate.collection.AbstractPersistentCollection.readSize(AbstractPersistentCollection.java:131)

TM.out log:

09-03-30 23:04:55,062 [http-8080-Processor24] addParticipant ( XAResourceTransaction: 3139322E3136382E302E322E746D30303332383030303331:3139322E3136382E302E322E746D333233 ) for transaction 192.168.0.2.tm0032800031
09-03-30 23:04:55,062 [http-8080-Processor24] XAResourceTransaction: 3139322E3136382E302E322E746D30303332383030303331:3139322E3136382E302E322E746D333233: about to switch to XAResource com.mysql.jdbc.jdbc2.optional.MysqlXAConnection@754a4a
09-03-30 23:04:55,062 [http-8080-Processor24] XAResourceTransaction 192.168.0.2.tm0032800031192.168.0.2.tm323: switched to XAResource com.mysql.jdbc.jdbc2.optional.MysqlXAConnection@754a4a
09-03-30 23:04:55,062 [http-8080-Processor24] XAResource.start ( 3139322E3136382E302E322E746D30303332383030303331:3139322E3136382E302E322E746D333233 , XAResource.TMNOFLAGS ) called on resource XA-CORE-TESTPROJECT-DATASOURCE represented by XAResource instance com.mysql.jdbc.jdbc2.optional.MysqlXAConnection@754a4a
09-03-30 23:04:55,062 [http-8080-Processor24] a TransactionContext: changing to state com.atomikos.datasource.xa.session.BranchEnlistedStateHandler@1482a89
09-03-30 23:04:55,062 [http-8080-Processor24] atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.ConnectionWrapper@e1ccdf: detected transaction com.atomikos.icatch.imp.CompositeTransactionImp@21e98d
09-03-30 23:04:55,062 [http-8080-Processor24] Coordinator 192.168.0.2.tm0032800031 entering state: ACTIVE
09-03-30 23:04:55,062 [http-8080-Processor24] Coordinator 192.168.0.2.tm0032800031 entered state: ACTIVE
09-03-30 23:04:55,062 [http-8080-Processor24] atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.ConnectionWrapper@e1ccdf: calling prepareStatement...
09-03-30 23:04:55,062 [http-8080-Processor24] atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.ConnectionWrapper@e1ccdf: prepareStatement returning com.mysql.jdbc.jdbc2.optional.PreparedStatementWrapper@1e076f3
09-03-30 23:04:55,093 [http-8080-Processor24] atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.ConnectionWrapper@e1ccdf: isClosed()...
09-03-30 23:04:55,093 [http-8080-Processor24] atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.ConnectionWrapper@e1ccdf: isClosed() returning false
09-03-30 23:04:55,093 [http-8080-Processor24] getCompositeTransaction()  returning instance with id 192.168.0.2.tm0032800031

09-03-30 23:04:55,093 [http-8080-Processor24] atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.ConnectionWrapper@e1ccdf: calling clearWarnings...
09-03-30 23:04:55,093 [http-8080-Processor24] atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.ConnectionWrapper@e1ccdf: clearWarnings returning null
09-03-30 23:04:55,093 [http-8080-Processor24] getCompositeTransaction()  returning instance with id 192.168.0.2.tm0032800031
09-03-30 23:04:55,093 [http-8080-Processor24] atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.ConnectionWrapper@e1ccdf: close()...
09-03-30 23:04:55,093 [http-8080-Processor24] a SessionHandleState with 1 context(s): entering notifySessionClosed
09-03-30 23:04:55,093 [http-8080-Processor24] a SessionHandleState with 1 context(s): delegeting session close to a TransactionContext
09-03-30 23:04:55,093 [http-8080-Processor24] XAResource.end ( 3139322E3136382E302E322E746D30303332383030303331:3139322E3136382E302E322E746D333233 , XAResource.TMSUCCESS ) called on resource XA-CORE-TESTPROJECT-DATASOURCE represented by XAResource instance com.mysql.jdbc.jdbc2.optional.MysqlXAConnection@754a4a
09-03-30 23:04:55,093 [http-8080-Processor24] a TransactionContext: changing state to com.atomikos.datasource.xa.session.BranchEndedStateHandler@3e9c6b
09-03-30 23:04:55,093 [http-8080-Processor24] a TransactionContext: changing to state com.atomikos.datasource.xa.session.BranchEndedStateHandler@3e9c6b
09-03-30 23:04:55,093 [http-8080-Processor24] atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.ConnectionWrapper@e1ccdf: closed.
09-03-30 23:04:55,093 [http-8080-Processor24] AtomikosDataSoureBean 'XA-CORE-TESTPROJECT-DATASOURCE': getConnection ( null )...
09-03-30 23:04:55,093 [http-8080-Processor24] AtomikosDataSoureBean 'XA-CORE-TESTPROJECT-DATASOURCE': init...
09-03-30 23:04:55,093 [http-8080-Processor24] getCompositeTransaction()  returning instance with id 192.168.0.2.tm0032800031
09-03-30 23:04:55,093 [http-8080-Processor24] an AtomikosXAPooledConnection with a SessionHandleState with 1 context(s): updating last time acquired
09-03-30 23:04:55,093 [http-8080-Processor24] an AtomikosXAPooledConnection with a SessionHandleState with 1 context(s): no test query, skipping test

09-03-30 23:04:55,093 [http-8080-Processor24] an AtomikosXAPooledConnection with a SessionHandleState with 1 context(s): creating connection proxy...
09-03-30 23:04:55,093 [http-8080-Processor24] a SessionHandleState with 1 context(s): notifySessionBorrowed
09-03-30 23:04:55,093 [http-8080-Processor24] a TransactionContext: changing to state com.atomikos.datasource.xa.session.NotInBranchStateHandler@1ffa176
09-03-30 23:04:55,093 [http-8080-Processor24] getCompositeTransaction()  returning instance with id 192.168.0.2.tm0032800031
09-03-30 23:04:55,093 [http-8080-Processor24] atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.ConnectionWrapper@e1ccdf: calling toString...
09-03-30 23:04:55,093 [http-8080-Processor24] atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.ConnectionWrapper@e1ccdf: toString returning com.mysql.jdbc.jdbc2.optional.ConnectionWrapper@e1ccdf
09-03-30 23:04:55,093 [http-8080-Processor24] an AtomikosXAPooledConnection with a SessionHandleState with 2 context(s): returning proxy com.mysql.jdbc.jdbc2.optional.ConnectionWrapper@e1ccdf
09-03-30 23:04:55,093 [http-8080-Processor24] atomikos connection pool 'XA-CORE-TESTPROJECT-DATASOURCE': recycling connection from pool...
09-03-30 23:04:55,093 [http-8080-Processor24] getCompositeTransaction()  returning instance with id 192.168.0.2.tm0032800031
09-03-30 23:04:55,093 [http-8080-Processor24] atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.ConnectionWrapper@e1ccdf: calling toString...
09-03-30 23:04:55,093 [http-8080-Processor24] atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.ConnectionWrapper@e1ccdf: toString returning com.mysql.jdbc.jdbc2.optional.ConnectionWrapper@e1ccdf
09-03-30 23:04:55,093 [http-8080-Processor24] AtomikosDataSoureBean 'XA-CORE-TESTPROJECT-DATASOURCE': returning com.mysql.jdbc.jdbc2.optional.ConnectionWrapper@e1ccdf
09-03-30 23:04:55,093 [http-8080-Processor24] getCompositeTransaction()  returning instance with id 192.168.0.2.tm0032800031
09-03-30 23:04:55,093 [http-8080-Processor24] atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.ConnectionWrapper@e1ccdf: notifyBeforeUse a SessionHandleState with 2 context(s)
09-03-30 23:04:55,093 [http-8080-Processor24] getCompositeTransaction()  returning instance with id 192.168.0.2.tm0032800031

23:04:55,093 [http-8080-Processor24] a SessionHandleState with 2 context(s): checking XA context for transaction com.atomikos.icatch.imp.CompositeTransactionImp@21e98d
09-03-30 23:04:55,093 [http-8080-Processor24] Coordinator 192.168.0.2.tm0032800031 entering state: ACTIVE
09-03-30 23:04:55,093 [http-8080-Processor24] Coordinator 192.168.0.2.tm0032800031 entered state: ACTIVE
09-03-30 23:04:55,093 [http-8080-Processor24] addParticipant ( XAResourceTransaction: 3139322E3136382E302E322E746D30303332383030303331:3139322E3136382E302E322E746D333233 ) for transaction 192.168.0.2.tm0032800031
09-03-30 23:04:55,093 [http-8080-Processor24] XAResourceTransaction: 3139322E3136382E302E322E746D30303332383030303331:3139322E3136382E302E322E746D333233: about to switch to XAResource com.mysql.jdbc.jdbc2.optional.MysqlXAConnection@754a4a
09-03-30 23:04:55,093 [http-8080-Processor24] XAResourceTransaction 192.168.0.2.tm0032800031192.168.0.2.tm323: switched to XAResource com.mysql.jdbc.jdbc2.optional.MysqlXAConnection@754a4a
09-03-30 23:04:55,093 [http-8080-Processor24] XA resource 'XA-CORE-TESTPROJECT-DATASOURCE': resume for XID '3139322E3136382E302E322E746D30303332383030303331:3139322E3136382E302E322E746D333233' raised -5: invalid arguments were given for the XA operation
09-03-30 23:04:55,093 [http-8080-Processor24] Error enlisting in transaction - connection might be broken? Please check the logs for more information...
09-03-30 23:04:55,093 [http-8080-Processor24] getCompositeTransaction()  returning instance with id 192.168.0.2.tm0032800031
09-03-30 23:04:55,093 [http-8080-Processor24] getCompositeTransaction()  returning instance with id 192.168.0.2.tm0032800031
09-03-30 23:04:55,093 [http-8080-Processor24] atomikos connection proxy for com.mysql.jdbc.jdbc2.optional.ConnectionWrapper@e1ccdf: isClosed()...

I think this issue also relates to

http://www.atomikos.com/Documentation/KnownProblems#MySQL_XA_bug

But how does the application work properly with Spring-3.5.3 ??

Not sure, but the reason could be in a different approach in reusing connections for the different Spring releases.

Whether or not a connection is closed in between reuse will determine whether or not certain XA interactions are necessary - and if those interactions are not supported by MySQL then, well, ...

HTH