users@glassfish.java.net

JMS and transaction issue

From: Theodor Richard <theodor.richard_at_googlemail.com>
Date: Thu, 6 Jan 2011 18:48:25 +0100

I have an issue with JMS and transactions which I do not completely
understand. My application has one JDBC resource and two JMS queues. The
message producers for the queues are created within the same stateless
session bean from the the same jms session object. The way I use the queues
is as follows: An entitiy is created and its id is saved as a property in
the JMS message and sent to the queue. The creation of the entity and the
submission to the queue happen in the same transaction. My message driven
bean then retrieves the entity from the database via the ID in the JMS
message and processes it.

The code looks roughly like this:

public long doSomething(String message) {
        SomeObject obj = new SomeObject(message);
        entityManager.persist(obj)

       // submit to JMS queue
      try {
            Message jmsMessage = session.createMessage();
            jmsMessage.setLongProperty("id", obj.getId());
            messageProducer.send(jmsMessage);
        } catch (JMSException ex) {

 Logger.getLogger(NotificationQueue.class.getName()).log(Level.SEVERE, null,
ex);
        }

       return obj.getId();
}

the MDB's onMessage method:

public void onMessage(Message message) {
        Long id;
        try {
            id = message.getLongProperty("id");
        } catch (Exception ex) {

 Logger.getLogger(AlertMessageListener.class.getName()).log(Level.SEVERE,
null, ex);
            throw new EJBException(ex);
        }

        SomeObject obj = entityManager.find(SomeObject.class, id);
        obj.process();
 }

When the entity is retrieved from the database in the onMessage() method,
the following exception is in the log file:

FINE: ENTRY com.test.app.alert.control.AlertMessageListener onMessage
FINE: ENTRY com.test.app.alert.control.MessageDao find
FINER: client acquired: 2104888816
FINER: TX binding to tx mgr, status=STATUS_ACTIVE
FINER: acquire unit of work: 1368213481
FINEST: Execute query ReadObjectQuery(name="readObject"
referenceClass=Message sql="SELECT ID, DTYPE, MESSAGE, REPORTTIME,
SENDER_USERNAME, ALERTSTATE, TIMERHANDLE, CATEGORY_ID, PRIORITY_PRIOLEVEL
FROM MESSAGE WHERE (ID = ?)")
SEVERE: prepareTransaction (XA) on JMSService:jmsdirect failed for
connectionId:7979865462417759232 due to Unknown JMSService server error
ERROR: com.sun.messaging.jmq.jmsserver.util.BrokerException: Bad transaction
state transition. Cannot perform operation PREPARE_TRANSACTION(56)
(XAFlag=null) on a transaction in state STARTED(1).
WARNING: JTS5031: Exception [java.lang.RuntimeException:
javax.transaction.xa.XAException] on Resource [prepare] operation.
SEVERE: rollbackTransaction (XA) on JMSService:jmsdirect failed for
connectionId:7979865462417759232:transactionId=7979865462479908608 due to
Unknown JMSService server error ERROR:
com.sun.messaging.jmq.jmsserver.util.BrokerException: Bad transaction state
transition. Cannot perform operation ROLLBACK_TRANSACTION(48) (XAFlag=null)
on a transaction in state STARTED(1).
WARNING: JTS5068: Unexpected error occurred in rollback
javax.transaction.xa.XAException
        at
com.sun.messaging.jms.ra.DirectXAResource.rollback(DirectXAResource.java:703)
        at
com.sun.jts.jta.TransactionState.rollback(TransactionState.java:193)
        at
com.sun.jts.jtsxa.OTSResourceImpl.rollback(OTSResourceImpl.java:333)
        at
com.sun.jts.CosTransactions.RegisteredResources.distributeRollback(RegisteredResources.java:1063)
        at
com.sun.jts.CosTransactions.TopCoordinator.rollback(TopCoordinator.java:2299)
        at
com.sun.jts.CosTransactions.CoordinatorTerm.commit(CoordinatorTerm.java:420)
        at
com.sun.jts.CosTransactions.TerminatorImpl.commit(TerminatorImpl.java:250)
        at
com.sun.jts.CosTransactions.CurrentImpl.commit(CurrentImpl.java:623)
        at
com.sun.jts.jta.TransactionManagerImpl.commit(TransactionManagerImpl.java:319)
        at
com.sun.enterprise.transaction.jts.JavaEETransactionManagerJTSDelegate.commitDistributedTransaction(JavaEETransactionManagerJTSDelegate.java:173)
        at
com.sun.enterprise.transaction.JavaEETransactionManagerSimplified.commit(JavaEETransactionManagerSimplified.java:873)
        at
com.sun.ejb.containers.BaseContainer.completeNewTx(BaseContainer.java:5115)
        at
com.sun.ejb.containers.BaseContainer.postInvokeTx(BaseContainer.java:4880)
        at
com.sun.ejb.containers.MessageBeanContainer.afterMessageDeliveryInternal(MessageBeanContainer.java:1207)
        at
com.sun.ejb.containers.MessageBeanContainer.afterMessageDelivery(MessageBeanContainer.java:1180)
        at
com.sun.ejb.containers.MessageBeanListenerImpl.afterMessageDelivery(MessageBeanListenerImpl.java:86)
        at
com.sun.enterprise.connectors.inbound.MessageEndpointInvocationHandler.invoke(MessageEndpointInvocationHandler.java:143)
        at $Proxy260.afterDelivery(Unknown Source)
        at
com.sun.messaging.jms.ra.OnMessageRunner.run(OnMessageRunner.java:328)
        at
com.sun.enterprise.connectors.work.OneWork.doWork(OneWork.java:114)
        at
com.sun.corba.ee.impl.orbutil.threadpool.ThreadPoolImpl$WorkerThread.performWork(ThreadPoolImpl.java:496)
        at
com.sun.corba.ee.impl.orbutil.threadpool.ThreadPoolImpl$WorkerThread.run(ThreadPoolImpl.java:537)
Caused by: com.sun.messaging.jmq.jmsservice.JMSServiceException:
rollbackTransaction: rollback transaction failed. Connection ID:
7979865462417759232, Transaction ID: 7979865462479908608, XID: null
        at
com.sun.messaging.jmq.jmsserver.service.imq.IMQDirectService.rollbackTransaction(IMQDirectService.java:1827)
        at
com.sun.messaging.jms.ra.DirectXAResource.rollback(DirectXAResource.java:672)
        ... 21 more
Caused by: com.sun.messaging.jmq.jmsserver.util.BrokerException: Bad
transaction state transition. Cannot perform operation
ROLLBACK_TRANSACTION(48) (XAFlag=null) on a transaction in state STARTED(1).
        at
com.sun.messaging.jmq.jmsserver.data.TransactionState.nextState(TransactionState.java:449)
        at
com.sun.messaging.jmq.jmsserver.data.handlers.TransactionHandler.preRollback(TransactionHandler.java:1586)
        at
com.sun.messaging.jmq.jmsserver.data.protocol.ProtocolImpl.rollbackTransaction(ProtocolImpl.java:777)
        at
com.sun.messaging.jmq.jmsserver.service.imq.IMQDirectService.rollbackTransaction(IMQDirectService.java:1816)
        ... 22 more

FINER: TX afterCompletion callback, status=ROLLEDBACK
FINER: release unit of work
FINER: client released
FINEST: Register the existing object
com.test.app.alert.entity.AlertMessage_at_7981d22
FINER: end unit of work commit
FINEST: Register the existing object Mailserver
FINEST: Register the existing object Low
FINEST: Register the existing object u0 u0 (u0)
FINEST: Register the existing object Sankt Augustin
FINE: RETURN com.test.app.alert.control.MessageDao find
...
WARNING: javax.ejb.EJBException
javax.ejb.EJBException: Transaction aborted
        at
com.sun.ejb.containers.BaseContainer.completeNewTx(BaseContainer.java:5121)
        at
com.sun.ejb.containers.BaseContainer.postInvokeTx(BaseContainer.java:4880)
        at
com.sun.ejb.containers.MessageBeanContainer.afterMessageDeliveryInternal(MessageBeanContainer.java:1207)
        at
com.sun.ejb.containers.MessageBeanContainer.afterMessageDelivery(MessageBeanContainer.java:1180)
        at
com.sun.ejb.containers.MessageBeanListenerImpl.afterMessageDelivery(MessageBeanListenerImpl.java:86)
        at
com.sun.enterprise.connectors.inbound.MessageEndpointInvocationHandler.invoke(MessageEndpointInvocationHandler.java:143)
        at $Proxy260.afterDelivery(Unknown Source)
        at
com.sun.messaging.jms.ra.OnMessageRunner.run(OnMessageRunner.java:328)
        at
com.sun.enterprise.connectors.work.OneWork.doWork(OneWork.java:114)
        at
com.sun.corba.ee.impl.orbutil.threadpool.ThreadPoolImpl$WorkerThread.performWork(ThreadPoolImpl.java:496)
        at
com.sun.corba.ee.impl.orbutil.threadpool.ThreadPoolImpl$WorkerThread.run(ThreadPoolImpl.java:537)
Caused by: javax.transaction.RollbackException
        at
com.sun.jts.jta.TransactionManagerImpl.commit(TransactionManagerImpl.java:321)
        at
com.sun.enterprise.transaction.jts.JavaEETransactionManagerJTSDelegate.commitDistributedTransaction(JavaEETransactionManagerJTSDelegate.java:173)
        at
com.sun.enterprise.transaction.JavaEETransactionManagerSimplified.commit(JavaEETransactionManagerSimplified.java:873)
        at
com.sun.ejb.containers.BaseContainer.completeNewTx(BaseContainer.java:5115)
        ... 10 more

The following INFO was in the log file a little bit before (after the entity
was created):

INFO: DXAR:start():Warning:Received diff Xid for open txnId:switching
transactionId:
DXAR Xid=(GlobalTransactionID=[B_at_4eec2030, BranchQualifier=[B_at_703557ca)
DXAR TXid=7979865462479908608
got Xid=(GlobalTransactionID=[B_at_3e16c853, BranchQualifier=[B_at_49b9e0fd)
got TXid=7979865462480472064

What exactly does this exception mean:

Bad transaction state transition. Cannot perform operation
ROLLBACK_TRANSACTION(48) (XAFlag=null) on a transaction in state STARTED(1).

I'm using Glassfish v3.1-b35 with JPA 2.0 (and Apache Derby) and the
standard JMS provider shipped with GF. Transactions settings are default as
well as the JMS resources (EMBEDDED mode). Transactions are
container-managed. Any ideas what is going wrong here? The exception happens
pretty often.

Regards,
Theodor