users@glassfish.java.net

Re: MDB message TTL and afterDelivery log spam

From: <glassfish_at_javadesktop.org>
Date: Wed, 30 Jun 2010 09:34:48 PDT

This code will get the Exception repeatably:

Producer:

        QueueConnection qc = null;
        QueueSession qs = null;
        try {
            InitialContext ctx = new InitialContext();
            QueueConnectionFactory qcf = (QueueConnectionFactory) ctx.lookup("jms/MessageFactory");
            qc = qcf.createQueueConnection();
            qs = qc.createQueueSession(false, QueueSession.AUTO_ACKNOWLEDGE);
            QueueSender sender = qs.createSender((Queue) ctx.lookup("jms/TestQueue"));
            sender.setTimeToLive(60000);
            TextMessage bmsg = qs.createTextMessage();
            bmsg.setText("content");
            sender.send(bmsg);
        } catch (Exception ex) {
            Logger.getLogger(TimerBean.class.getName()).log(Level.SEVERE, null, ex);
        } finally {
            if (qs != null) {
                try {
                    qs.close();
                } catch (JMSException ex) {
                    Logger.getLogger(TimerBean.class.getName()).log(Level.SEVERE, null, ex);
                }
            }
            if (qc != null) {
                try {
                    qc.close();
                } catch (JMSException ex) {
                    Logger.getLogger(TimerBean.class.getName()).log(Level.SEVERE, null, ex);
                }
            }
        }

MDB:

import java.util.logging.Level;
import java.util.logging.Logger;
import javax.ejb.ActivationConfigProperty;
import javax.ejb.MessageDriven;
import javax.jms.Message;
import javax.jms.MessageListener;
import javax.jms.TextMessage;

@MessageDriven(mappedName = "jms/TestQueue", activationConfig = {
        @ActivationConfigProperty(propertyName = "acknowledgeMode", propertyValue = "Auto-acknowledge"),
        @ActivationConfigProperty(propertyName = "destinationType", propertyValue = "javax.jms.Queue")
    })
public class MessageProcessorBean implements MessageListener {
    
    public void onMessage(Message message) {
        try {
            Logger.getLogger(MessageProcessorBean.class.getName()).log(Level.INFO, "Waiting.");
            Thread.sleep(70000);
            Logger.getLogger(MessageProcessorBean.class.getName()).log(Level.INFO, ((TextMessage) message).getText());
        } catch (Exception ex) {
            Logger.getLogger(MessageProcessorBean.class.getName()).log(Level.SEVERE, null, ex);
        }
    }
}

Stack Trace:

[#|2010-06-30T17:16:48.984+0100|INFO|sun-appserver2.1|com.ngc.msg.MessageProcessorBean|_ThreadID=23;_ThreadName=p: thread-pool-1; w: 106;|Waiting.|#]

[#|2010-06-30T17:17:58.984+0100|INFO|sun-appserver2.1|com.ngc.msg.MessageProcessorBean|_ThreadID=23;_ThreadName=p: thread-pool-1; w: 106;|content|#]

[#|2010-06-30T17:17:58.984+0100|WARNING|sun-appserver2.1|javax.enterprise.system.stream.err|_ThreadID=23;_ThreadName=p: thread-pool-1; w: 106;_RequestID=2b5dccd1-31c9-485f-9d69-fb4f6fc7c403;|
MQRA:OMR:run:JMSException on message acknowledgement:Rolling back if in txn|#]

[#|2010-06-30T17:17:58.984+0100|WARNING|sun-appserver2.1|javax.enterprise.system.stream.err|_ThreadID=23;_ThreadName=p: thread-pool-1; w: 106;_RequestID=2b5dccd1-31c9-485f-9d69-fb4f6fc7c403;|
com.sun.messaging.jms.JMSException: [ACKNOWLEDGE_REPLY(25)] [C4036]: A broker error occurred. :[409] [B1261]: Transaction acknowledgement could not be added because message 2219-10.64.11.34(e7:2b:6d:43:88:c8)-1241-1277914608765[[consumer:5015085331185179136, type=NONE]:[consumer:0, type=CLIENT_ACKNOWLEDGE]]TUID=5015085331216935168 has already been removed user=guest, broker=blade4.wxirad.ng:7677(2947)
        at com.sun.messaging.jmq.jmsclient.ProtocolHandler.throwServerErrorException(ProtocolHandler.java:3982)
        at com.sun.messaging.jmq.jmsclient.ProtocolHandler.acknowledge(ProtocolHandler.java:2605)
        at com.sun.messaging.jmq.jmsclient.SessionImpl.doAcknowledge(SessionImpl.java:1382)
        at com.sun.messaging.jmq.jmsclient.SessionImpl.acknowledgeFromRAEndpoint(SessionImpl.java:1074)
        at com.sun.messaging.jms.ra.OnMessageRunner.run(OnMessageRunner.java:267)
        at com.sun.enterprise.connectors.work.OneWork.doWork(OneWork.java:76)
        at com.sun.corba.ee.impl.orbutil.threadpool.ThreadPoolImpl$WorkerThread.run(ThreadPoolImpl.java:555)
|#]

[#|2010-06-30T17:17:59.000+0100|INFO|sun-appserver2.1|javax.enterprise.system.stream.out|_ThreadID=23;_ThreadName=p: thread-pool-1; w: 106;|
com.sun.messaging.jms.JMSException: [END_TRANSACTION_REPLY(59)] [C4036]: A broker error occurred. :[304] Cannot perform operation END_TRANSACTION(58) (XAFlag=0x4000000:TMSUCCESS) for the transaction has been set to FAILED from STARTED(1) user=guest, broker=blade4.wxirad.ng:7677(2947)
        at com.sun.messaging.jmq.jmsclient.ProtocolHandler.throwServerErrorException(ProtocolHandler.java:3982)
        at com.sun.messaging.jmq.jmsclient.ProtocolHandler.endTransaction(ProtocolHandler.java:2811)
        at com.sun.messaging.jmq.jmsclient.XAResourceForRA.end(XAResourceForRA.java:278)
        at com.sun.jts.jta.TransactionState.beforeCompletion(TransactionState.java:161)
        at com.sun.jts.jta.SynchronizationImpl.before_completion(SynchronizationImpl.java:133)
        at com.sun.jts.CosTransactions.RegisteredSyncs.distributeBefore(RegisteredSyncs.java:158)
        at com.sun.jts.CosTransactions.TopCoordinator.beforeCompletion(TopCoordinator.java:2548)
        at com.sun.jts.CosTransactions.CoordinatorTerm.commit(CoordinatorTerm.java:278)
        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:309)
        at com.sun.enterprise.distributedtx.J2EETransactionManagerImpl.commit(J2EETransactionManagerImpl.java:1003)
        at com.sun.enterprise.distributedtx.J2EETransactionManagerOpt.commit(J2EETransactionManagerOpt.java:398)
        at com.sun.ejb.containers.BaseContainer.completeNewTx(BaseContainer.java:3817)
        at com.sun.ejb.containers.BaseContainer.postInvokeTx(BaseContainer.java:3596)
        at com.sun.ejb.containers.MessageBeanContainer.afterMessageDeliveryInternal(MessageBeanContainer.java:1226)
        at com.sun.ejb.containers.MessageBeanContainer.afterMessageDelivery(MessageBeanContainer.java:1197)
        at com.sun.ejb.containers.MessageBeanListenerImpl.afterMessageDelivery(MessageBeanListenerImpl.java:79)
        at com.sun.enterprise.connectors.inflow.MessageEndpointInvocationHandler.invoke(MessageEndpointInvocationHandler.java:139)
        at $Proxy44.afterDelivery(Unknown Source)
        at com.sun.messaging.jms.ra.OnMessageRunner.run(OnMessageRunner.java:324)
        at com.sun.enterprise.connectors.work.OneWork.doWork(OneWork.java:76)
        at com.sun.corba.ee.impl.orbutil.threadpool.ThreadPoolImpl$WorkerThread.run(ThreadPoolImpl.java:555)
|#]

[#|2010-06-30T17:17:59.000+0100|WARNING|sun-appserver2.1|javax.enterprise.system.core.transaction|_ThreadID=23;_ThreadName=p: thread-pool-1; w: 106;_RequestID=2b5dccd1-31c9-485f-9d69-fb4f6fc7c403;|JTS5064: Unexpected exception occurred while delisting the resource
javax.transaction.xa.XAException
        at com.sun.messaging.jmq.jmsclient.XAResourceForRA.end(XAResourceForRA.java:282)
        at com.sun.jts.jta.TransactionState.beforeCompletion(TransactionState.java:161)
        at com.sun.jts.jta.SynchronizationImpl.before_completion(SynchronizationImpl.java:133)
        at com.sun.jts.CosTransactions.RegisteredSyncs.distributeBefore(RegisteredSyncs.java:158)
        at com.sun.jts.CosTransactions.TopCoordinator.beforeCompletion(TopCoordinator.java:2548)
        at com.sun.jts.CosTransactions.CoordinatorTerm.commit(CoordinatorTerm.java:278)
        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:309)
        at com.sun.enterprise.distributedtx.J2EETransactionManagerImpl.commit(J2EETransactionManagerImpl.java:1003)
        at com.sun.enterprise.distributedtx.J2EETransactionManagerOpt.commit(J2EETransactionManagerOpt.java:398)
        at com.sun.ejb.containers.BaseContainer.completeNewTx(BaseContainer.java:3817)
        at com.sun.ejb.containers.BaseContainer.postInvokeTx(BaseContainer.java:3596)
        at com.sun.ejb.containers.MessageBeanContainer.afterMessageDeliveryInternal(MessageBeanContainer.java:1226)
        at com.sun.ejb.containers.MessageBeanContainer.afterMessageDelivery(MessageBeanContainer.java:1197)
        at com.sun.ejb.containers.MessageBeanListenerImpl.afterMessageDelivery(MessageBeanListenerImpl.java:79)
        at com.sun.enterprise.connectors.inflow.MessageEndpointInvocationHandler.invoke(MessageEndpointInvocationHandler.java:139)
        at $Proxy44.afterDelivery(Unknown Source)
        at com.sun.messaging.jms.ra.OnMessageRunner.run(OnMessageRunner.java:324)
        at com.sun.enterprise.connectors.work.OneWork.doWork(OneWork.java:76)
        at com.sun.corba.ee.impl.orbutil.threadpool.ThreadPoolImpl$WorkerThread.run(ThreadPoolImpl.java:555)
Caused by: com.sun.messaging.jms.JMSException: [END_TRANSACTION_REPLY(59)] [C4036]: A broker error occurred. :[304] Cannot perform operation END_TRANSACTION(58) (XAFlag=0x4000000:TMSUCCESS) for the transaction has been set to FAILED from STARTED(1) user=guest, broker=blade4.wxirad.ng:7677(2947)
        at com.sun.messaging.jmq.jmsclient.ProtocolHandler.throwServerErrorException(ProtocolHandler.java:3982)
        at com.sun.messaging.jmq.jmsclient.ProtocolHandler.endTransaction(ProtocolHandler.java:2811)
        at com.sun.messaging.jmq.jmsclient.XAResourceForRA.end(XAResourceForRA.java:278)
        ... 20 more
|#]

[#|2010-06-30T17:17:59.015+0100|INFO|sun-appserver2.1|javax.enterprise.system.container.ejb.mdb|_ThreadID=23;_ThreadName=p: thread-pool-1; w: 106;TestApp:MessageProcessorBean;javax.ejb.EJBException: Transaction aborted; nested exception is: javax.transaction.RollbackException;|MDB00037: [TestApp:MessageProcessorBean]: Message-driven bean invocation exception: [javax.ejb.EJBException: Transaction aborted; nested exception is: javax.transaction.RollbackException]|#]

[#|2010-06-30T17:17:59.015+0100|INFO|sun-appserver2.1|javax.enterprise.system.container.ejb.mdb|_ThreadID=23;_ThreadName=p: thread-pool-1; w: 106;|javax.ejb.EJBException
javax.ejb.EJBException: Transaction aborted; nested exception is: javax.transaction.RollbackException
javax.transaction.RollbackException
        at com.sun.jts.jta.TransactionManagerImpl.commit(TransactionManagerImpl.java:311)
        at com.sun.enterprise.distributedtx.J2EETransactionManagerImpl.commit(J2EETransactionManagerImpl.java:1003)
        at com.sun.enterprise.distributedtx.J2EETransactionManagerOpt.commit(J2EETransactionManagerOpt.java:398)
        at com.sun.ejb.containers.BaseContainer.completeNewTx(BaseContainer.java:3817)
        at com.sun.ejb.containers.BaseContainer.postInvokeTx(BaseContainer.java:3596)
        at com.sun.ejb.containers.MessageBeanContainer.afterMessageDeliveryInternal(MessageBeanContainer.java:1226)
        at com.sun.ejb.containers.MessageBeanContainer.afterMessageDelivery(MessageBeanContainer.java:1197)
        at com.sun.ejb.containers.MessageBeanListenerImpl.afterMessageDelivery(MessageBeanListenerImpl.java:79)
        at com.sun.enterprise.connectors.inflow.MessageEndpointInvocationHandler.invoke(MessageEndpointInvocationHandler.java:139)
        at $Proxy44.afterDelivery(Unknown Source)
        at com.sun.messaging.jms.ra.OnMessageRunner.run(OnMessageRunner.java:324)
        at com.sun.enterprise.connectors.work.OneWork.doWork(OneWork.java:76)
        at com.sun.corba.ee.impl.orbutil.threadpool.ThreadPoolImpl$WorkerThread.run(ThreadPoolImpl.java:555)
javax.ejb.EJBException: Transaction aborted; nested exception is: javax.transaction.RollbackException
        at com.sun.ejb.containers.BaseContainer.completeNewTx(BaseContainer.java:3823)
        at com.sun.ejb.containers.BaseContainer.postInvokeTx(BaseContainer.java:3596)
        at com.sun.ejb.containers.MessageBeanContainer.afterMessageDeliveryInternal(MessageBeanContainer.java:1226)
        at com.sun.ejb.containers.MessageBeanContainer.afterMessageDelivery(MessageBeanContainer.java:1197)
        at com.sun.ejb.containers.MessageBeanListenerImpl.afterMessageDelivery(MessageBeanListenerImpl.java:79)
        at com.sun.enterprise.connectors.inflow.MessageEndpointInvocationHandler.invoke(MessageEndpointInvocationHandler.java:139)
        at $Proxy44.afterDelivery(Unknown Source)
        at com.sun.messaging.jms.ra.OnMessageRunner.run(OnMessageRunner.java:324)
        at com.sun.enterprise.connectors.work.OneWork.doWork(OneWork.java:76)
        at com.sun.corba.ee.impl.orbutil.threadpool.ThreadPoolImpl$WorkerThread.run(ThreadPoolImpl.java:555)
|#]
[Message sent by forum member 'rjg71']

http://forums.java.net/jive/thread.jspa?messageID=476432