Problem after upgrading the Transaction manager to jbossts-j
Hi,
I have upgraded the default transaction manager that comes along with JBOSS 4.0.4GA to JbossTS JTA v4.2.3GA and since then facing some problem.
The problem occurs when the server recieves a JMS message from a client. The producer also runs on JBOSS4.0.4GA, but has not been upgraded to use the new Transaction manager.
Following is the snippet of the log:-
2007-08-06 11:41:34,755 246510229 TRACE [org.jboss.ejb.plugins.LogInterceptor] (JMS SessionPool Worker-5:) End method=onMessage 2007-08-06 11:41:34,755 246510229 TRACE [org.jboss.jms.asf.StdServerSession] (JMS SessionPool Worker-5:) Commiting the JMS transaction 2007-08-06 11:41:34,757 246510231 DEBUG [com.pindartech.clipper.common.LogDebugMessages] (JMS SessionPool Worker-5:) <FileHelperMgrBean::beforeCompletion()> : Called on com.pindartech.clipper.file.sb_filehelper.FileHelperMgrBean@ef50f7 2007-08-06 11:41:34,758 246510232 TRACE [org.jboss.mq.SpyXAResource] (JMS SessionPool Worker-5:) End xid=< 131075, 30, 28, 1-ac8ab33:9003:46b37e5b:3ee327ac8ab33:9003:46b37e5b:3ee328>, flags=67108864 SpyXAResource[session=SpySession@2158344[tx=true txid=< 131075, 30, 28, 1-ac8ab33:9003:46b37e5b:3ee327ac8ab33:9003:46b37e5b:3ee328> XA RUNNING connection=Connection@435999[token=ConnectionToken:ID:1223/d4524629a305f4b8e08e676309238f9b rcvstate=STARTED]]] 2007-08-06 11:41:34,758 246510232 TRACE [org.jboss.mq.SpySession] (JMS SessionPool Worker-5:) Unsetting current tx xid=< 131075, 30, 28, 1-ac8ab33:9003:46b37e5b:3ee327ac8ab33:9003:46b37e5b:3ee328> previous: < 131075, 30, 28, 1-ac8ab33:9003:46b37e5b:3ee327ac8ab33:9003:46b37e5b:3ee328> SpySession@2158344[tx=true txid=< 131075, 30, 28, 1-ac8ab33:9003:46b37e5b:3ee327ac8ab33:9003:46b37e5b:3ee328> XA RUNNING connection=Connection@435999[token=ConnectionToken:ID:1223/d4524629a305f4b8e08e676309238f9b rcvstate=STARTED]] 2007-08-06 11:41:34,758 246510232 TRACE [org.jboss.mq.SpyXAResource] (JMS SessionPool Worker-5:) Prepare xid=< 131075, 30, 28, 1-ac8ab33:9003:46b37e5b:3ee327ac8ab33:9003:46b37e5b:3ee328> SpyXAResource[session=SpySession@2158344[tx=true txid=null XA RUNNING connection=Connection@435999[token=ConnectionToken:ID:1223/d4524629a305f4b8e08e676309238f9b rcvstate=STARTED]]] 2007-08-06 11:41:34,759 246510233 TRACE [org.jboss.mq.Connection] (JMS SessionPool Worker-5:) Transact request=org.jboss.mq.TransactionRequest@21f4e1 Connection@435999[token=ConnectionToken:ID:1223/d4524629a305f4b8e08e676309238f9b rcvstate=STARTED] 2007-08-06 11:41:34,759 246510233 TRACE [org.jboss.mq.il.uil2.SocketManager] (JMS SessionPool Worker-5:) Begin internalSendMessage, round-trip msg=org.jboss.mq.il.uil2.msgs.TransactMsg22275058[msgType: m_transact, msgID: -2147467301, error: null] 2007-08-06 11:41:34,759 246510233 TRACE [org.jboss.mq.il.uil2.SocketManager] (UIL2.SocketManager.WriteTask#20 client=10.200.171.52:8193:) Write msg: org.jboss.mq.il.uil2.msgs.TransactMsg22275058[msgType: m_transact, msgID: -2147467301, error: null] 2007-08-06 11:41:34,814 246510288 TRACE [org.jboss.mq.il.uil2.SocketManager] (UIL2.SocketManager.ReadTask#19 client=10.200.171.52:8193:) Exiting on IOE java.io.EOFException at java.io.ObjectInputStream$BlockDataInputStream.readByte(ObjectInputStream.java:2603) at java.io.ObjectInputStream.readByte(ObjectInputStream.java:845) at org.jboss.mq.il.uil2.SocketManager$ReadTask.run(SocketManager.java:317) at java.lang.Thread.run(Thread.java:534) 2007-08-06 11:41:34,815 246510289 TRACE [org.jboss.mq.Connection] (UIL2.SocketManager.ReadTask#19 client=10.200.171.52:8193:) Notified of failure reason=Exiting on IOE Connection@435999[token=ConnectionToken:ID:1223/d4524629a305f4b8e08e676309238f9b rcvstate=STARTED] java.io.EOFException at java.io.ObjectInputStream$BlockDataInputStream.readByte(ObjectInputStream.java:2603) at java.io.ObjectInputStream.readByte(ObjectInputStream.java:845) at org.jboss.mq.il.uil2.SocketManager$ReadTask.run(SocketManager.java:317) at java.lang.Thread.run(Thread.java:534) 2007-08-06 11:41:34,815 246510289 TRACE [org.jboss.mq.il.uil2.SocketManager] (JMS SessionPool Worker-5:) End internalSendMessage, msg=org.jboss.mq.il.uil2.msgs.TransactMsg22275058[msgType: m_transact, msgID: -2147467301, error: java.io.EOFException]
After the same set of exceptions for a while we get the following:-
2007-08-06 11:41:34,856 246510330 TRACE [org.jboss.mq.il.uil2.SocketManager] (JMSContainerInvoker(IPMReceiverBean) Reconnect:) Begin internalSendMessage, round-trip msg=org.jboss.mq.il.uil2.msgs.EnableConnectionMsg27960296[msgType: m_setEnabled, msgID: -2147467300, error: null] 2007-08-06 11:41:34,821 246510295 WARN [com.arjuna.ats.jta.logging.loggerI18N] (JMS SessionPool Worker-5:) [com.arjuna.ats.internal.jta.resources.arjunacore.preparefailed] [com.arjuna.ats.internal.jta.resources.arjunacore.preparefailed] XAResourceRecord.prepare - prepare failed with exception XAException.XAER_RMERR 2007-08-06 11:41:34,857 246510331 TRACE [org.jboss.mq.il.uil2.SocketManager] (UIL2.SocketManager.WriteTask#18 client=10.200.171.52:8193:) Write msg: org.jboss.mq.il.uil2.msgs.EnableConnectionMsg27960296[msgType: m_setEnabled, msgID: -2147467300, error: null] 2007-08-06 11:41:34,857 246510331 WARN [com.arjuna.ats.arjuna.logging.arjLoggerI18N] (JMS SessionPool Worker-5:) [com.arjuna.ats.arjuna.coordinator.BasicAction_50] - Prepare phase of action ac8ab33:9003:46b37e5b:3ee327 received heuristic decision: TwoPhaseOutcome.HEURISTIC_HAZARD 2007-08-06 11:41:34,857 246510331 WARN [com.arjuna.ats.arjuna.logging.arjLoggerI18N] (JMS SessionPool Worker-5:) [com.arjuna.ats.arjuna.coordinator.BasicAction_36] - BasicAction.End() - prepare phase of action-id ac8ab33:9003:46b37e5b:3ee327 failed. 2007-08-06 11:41:34,858 246510332 WARN [com.arjuna.ats.arjuna.logging.arjLoggerI18N] (JMS SessionPool Worker-5:) [com.arjuna.ats.arjuna.coordinator.BasicAction_37] - Received heuristic: TwoPhaseOutcome.HEURISTIC_HAZARD . 2007-08-06 11:41:34,858 246510332 WARN [com.arjuna.ats.arjuna.logging.arjLoggerI18N] (JMS SessionPool Worker-5:) [com.arjuna.ats.arjuna.coordinator.BasicAction_38] - Action Aborting ------ 2007-08-06 11:41:35,108 246510582 ERROR [org.jboss.jms.asf.StdServerSession] (JMS SessionPool Worker-5:) failed to commit/rollback javax.transaction.HeuristicMixedException at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1264) at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:135)
The second set of logs is anyways not related I guess, it may be because of the previous errors.
What I am trying to understand is why is the server trying to send a message back to the producer, after its completed processing the message. The producer would have anyways closed the session right?
Do we have to upgrade to the new JBOSS TS for the producer also?
Any help would be appreciated.