JMS transaction issue

Question

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@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@4eec2030, BranchQualifier=[B@703557ca) 
DXAR TXid=7979865462479908608
got   Xid=(GlobalTransactionID=[B@3e16c853, BranchQualifier=[B@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.

Answer 1

I've contacted Oracle regarding this: They recommend not to cache the JMS connections in the stateless session bean. Instead, connections should be acquired on-demand demand and released immediately. There is no performance overhead when doing this, since the connection handle is a thin wrapper around the actual physical connection (see section 6.4.3 of the Java EE Connector Architecture Specification). You can also refer to this thread in the glassfish mailing list for a similar problem.

Answer 2

Your problem is with the transaction management. Once you submit your message to the JMS destination the MDB picks it up in it's own transaction. This becomes a problem because your session bean submitting the message hasn't committed it's transaction yet. Now the MDB is trying to load an entity that doesn't exist.

Separate the submission code into it's own class and use a bean managed transaction.

Answer 3

I also had this issue with JMS where the entity transactions were being rolled back. I managed to fix it with a request for a new transaction using:

@TransactionAttribute(TransactionAttributeType.REQUIRES_NEW)

On the EJB that produces the messages to the Queue.

So my design is something like:

The producer:

@Stateless
@LocalBean
// Note here that a new transaction is required for this bean
@TransactionAttribute(TransactionAttributeType.REQUIRES_NEW) 
public class ProducerBean {

    @Resource(mappedName = "jms/theQueue")
    private Queue theQueue;

    @Inject
    private JMSContext jmsContext;


    private static final Logger logger = LoggerFactory.getLogger(ProducerBean.class);

    public void event(TheEvent theEvent) {
        // Place the message in the Queue
        try {
            jmsContext.createProducer().send(theQueue, theEvent);
            logger.info("send event|eventName:{}", theEvent.getEventName());
        } catch (Exception ex) {
            logger.error("Could not send the event|eventName:{}|error:{}", theEvent.getEventName(), ex.getMessage());
        }
    }
}

And my consumer is something like:

@MessageDriven(name = "TheConsumer", activationConfig = {
    @ActivationConfigProperty(propertyName = "destinationLookup", propertyValue = "jms/theQueue"),
    @ActivationConfigProperty(propertyName = "destinationType", propertyValue = "javax.jms.Queue"),
    @ActivationConfigProperty(propertyName = "acknowledgeMode", propertyValue = "Auto-acknowledge")
})
public class TheConsumer implements MessageListener {

    private static final Logger logger = LoggerFactory.getLogger(TheConsumer.class);

    @Override
    public void onMessage(Message message) {

        try {
            doSomething();

        } catch (JMSException ex) {
            logger.error("JMSException|could not retrieve the object from the message body - reason: {}", ex.getMessage());
        }
    }

}