Atomikos Forum

The following problem occurs when doing a commit after sending a JMS Messages and doing a database action.
I am using Atomikos 3.2.7 , Merlia 7.03 together with Spring 2.0.6 and Hibernate 3.2.3.ga
The following errors did not occur when testing, but they are occuring now in production environment. I don't know if it is related to the problem, but the SQL server is installed on a cluster of 2 servers, on both servers DTCProxy is installed.


Below you find the stacktrace and the debug logging from atomikos.


Stacktrace :

org.springframework.transaction.HeuristicCompletionException: Heuristic completion: outcome state is mixed; nested exception is javax.transaction.HeuristicMixedException: Heuristic Exception
Caused by: javax.transaction.HeuristicMixedException: Heuristic Exception
    at com.atomikos.icatch.jta.TransactionImp.commit(Unknown Source)
    at com.atomikos.icatch.jta.TransactionManagerImp.commit(Unknown Source)
    at com.atomikos.icatch.jta.UserTransactionImp.commit(Unknown Source)
    at org.springframework.transaction.jta.JtaTransactionManager.doCommit(JtaTransactionManager.java:842)
    at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:662)
    at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:632)
    at org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:314)
    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:117)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:166)
    at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
    at $Proxy142.execute(Unknown Source)
    at own.package.workflow.AutomaticTaskImplementation.runWithHibernate(AutomaticTaskImplementation.java:158)
    at own.package.scheduler.HibernateRunnable.doWithSession(HibernateRunnable.java:67)
    at own.package.scheduler.HibernateRunnable.run(HibernateRunnable.java:81)
    at own.package.workflow.GdpAutomaticTaskImplementation.run(GdpAutomaticTaskImplementation.java:26)
    at java.lang.Thread.run(Thread.java:595)

I allready enabled debug logging :

08-09-03 12:03:19,689 [main] USING com.atomikos.icatch.soap_commit_protocols = atomikos,wsat
08-09-03 12:03:19,689 [main] USING com.atomikos.icatch.console_file_name = tm.out
08-09-03 12:03:19,689 [main] USING com.atomikos.icatch.console_file_count = 1
08-09-03 12:03:19,689 [main] USING com.atomikos.icatch.automatic_resource_registration = true
08-09-03 12:03:19,689 [main] USING com.atomikos.icatch.client_demarcation = false
08-09-03 12:03:19,689 [main] USING com.atomikos.icatch.soap_request_threads = 1
08-09-03 12:03:19,689 [main] USING com.atomikos.icatch.threaded_2pc = true
08-09-03 12:03:19,689 [main] USING com.atomikos.icatch.soap_host_address = 10.100.1.22
08-09-03 12:03:19,689 [main] USING com.atomikos.icatch.serial_jta_transactions = true
08-09-03 12:03:19,689 [main] USING com.atomikos.icatch.log_base_dir = .\
08-09-03 12:03:19,689 [main] USING com.atomikos.icatch.console_log_level = WARN
08-09-03 12:03:19,689 [main] USING com.atomikos.icatch.max_actives = 50
08-09-03 12:03:19,689 [main] USING com.atomikos.icatch.soap_port = 8088
08-09-03 12:03:19,689 [main] USING com.atomikos.icatch.checkpoint_interval = 500
08-09-03 12:03:19,689 [main] USING com.atomikos.icatch.enable_logging = false
08-09-03 12:03:19,689 [main] USING com.atomikos.icatch.output_dir = .\
08-09-03 12:03:19,689 [main] USING com.atomikos.icatch.log_base_name = tmlog
08-09-03 12:03:19,689 [main] USING com.atomikos.icatch.console_file_limit = -1
08-09-03 12:03:19,689 [main] USING com.atomikos.icatch.max_timeout = 300000
08-09-03 12:03:19,689 [main] USING java.naming.factory.initial = com.sun.jndi.rmi.registry.RegistryContextFactory
08-09-03 12:03:19,689 [main] USING com.atomikos.icatch.tm_unique_name = 10.100.1.22.tm
08-09-03 12:03:19,689 [main] USING java.naming.provider.url = rmi://localhost:1099
08-09-03 12:03:19,689 [main] USING com.atomikos.icatch.service = com.atomikos.icatch.standalone.UserTransactionServiceFactory
08-09-03 12:03:34,626 [main] Mssql: refreshed XAResource
08-09-03 12:04:10,547 [main] Execution_Q: refreshed XAResource
08-09-03 12:05:17,125 [ClusterScheduler_Worker-0] JDBC ConnectionPool exhausted - allocated new connection: ExternalXAPooledConnectionImp1220436317125com.atomikos.jdbc.ExclusiveExternalXAPooledConnectionImp@abe02e
08-09-03 12:06:03,593 [WFT] JDBC ConnectionPool exhausted - allocated new connection: ExternalXAPooledConnectionImp1220436363593com.atomikos.jdbc.ExclusiveExternalXAPooledConnectionImp@b32b6
08-09-03 12:06:04,343 [WFT] JDBC ConnectionPool exhausted - allocated new connection: ExternalXAPooledConnectionImp1220436364343com.atomikos.jdbc.ExclusiveExternalXAPooledConnectionImp@1cad3a6
08-09-03 12:06:06,187 [WFT] JDBC ConnectionPool exhausted - allocated new connection: ExternalXAPooledConnectionImp1220436366187com.atomikos.jdbc.ExclusiveExternalXAPooledConnectionImp@1b4e557
08-09-03 12:06:12,765 [WFT] resume for XID 10.100.1.22.tm000380000310.100.1.22.tm22 raised -6: the XA resource did not expect this command in the current context
javax.transaction.xa.XAException: [TDS Driver]Connection is already enlist in a Distributed Transaction.
    at com.inet.tds.br.a(Unknown Source)
    at com.inet.tds.br.a(Unknown Source)
    at com.inet.tds.br.start(Unknown Source)
    at

com.atomikos.datasource.xa.XAResourceTransaction.resume(Unknown Source)
    at com.atomikos.jdbc.ConnectionProxy.invoke(Unknown Source)
    at $Proxy36.isClosed(Unknown Source)
    at own.package.persistence.RdbConnectionManager.getConnection(RdbConnectionManager.java:931)
    at own.package.persistence.RdbBroker.connection(RdbBroker.java:330)
    at own.package.persistence.RdbClassBroker.getInstance(RdbClassBroker.java:215)
    at own.package.persistence.PersistentBrokerManager.getInstance(PersistentBrokerManager.java:651)
    at own.package.workflow.persistence.WorkflowRdbDataManager.getTaskById(WorkflowRdbDataManager.java:2279)
    at own.package.workflow.WorkflowManager.getTaskById(WorkflowManager.java:1982)
    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:585)
    at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:296)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:177)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:144)
    at own.package.core.framework.aop.ProfilingInterceptor.invoke(ProfilingInterceptor.java:42)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:166)
    at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
    at $Proxy62.getTaskById(Unknown Source)
    at com.gudrun.morspeed2.web.workflow.helper.WorkflowHelperImpl.getTask(WorkflowHelperImpl.java:172)
    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:585)
    at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:296)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:177)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:144)
    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:107)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:166)
    at

own.package.core.framework.aop.ProfilingInterceptor.invoke(ProfilingInterceptor.java:42)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:166)
    at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
    at $Proxy63.getTask(Unknown Source)
    at com.gudrun.morspeed2.workflow.controller.SendMessageAsynchronouslyController.execute(SendMessageAsynchronouslyController.java:88)
    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:585)
    at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:296)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:177)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:144)
    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:107)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:166)
    at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
    at $Proxy142.execute(Unknown Source)
    at own.package.workflow.AutomaticTaskImplementation.runWithHibernate(AutomaticTaskImplementation.java:158)
    at com.gudrun.scheduler.HibernateRunnable.doWithSession(HibernateRunnable.java:67)
    at own.package.scheduler.HibernateRunnable.run(HibernateRunnable.java:81)
    at com.gdp3000.workflow.GdpAutomaticTaskImplementation.run(GdpAutomaticTaskImplementation.java:26)
    at java.lang.Thread.run(Thread.java:595)
08-09-03 12:07:03,623 [WFT] Local heuristic termination of coordinator 10.100.1.22.tm0003800003 with state ABORTING
08-09-03 12:07:03,670 [Atomikos:1] Local heuristic termination of coordinator 10.100.1.22.tm0003800003 with state HEUR_HAZARD
08-09-03 12:07:03,811 [Atomikos:1] Local heuristic termination of coordinator 10.100.1.22.tm0003800003 with state HEUR_HAZARD

Dennis,

It looks like a connection is being reused when it shouldn't. We would have to find out more to be conclusive.

Guy