Uploaded image for project: 'JBoss A-MQ'
  1. JBoss A-MQ
  2. ENTMQ-1160

When ActiveMQ encountered exception during rollback, the message is stuck instead of retry the rollback.

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Done
    • Icon: Major Major
    • JBoss A-MQ 6.3
    • JBoss A-MQ 6.1
    • rar-jee
    • Hide

      Test scenario:
      1. onMessage run in MDB
      2. onMessage sleep in TX timeout
      3. rollback start
      4. Insert the code using Byteman
      -------------
      RULE rollback2
      CLASS org.apache.activemq.transport.WireFormatNegotiator
      METHOD oneway(Object)
      AT ENTRY
      IF $1.toString().startsWith("MessageAck")
      DO traceln("*****************" + $1.toString()); throw new java.io.InterruptedIOException()
      ENDRULE
      -------------
      5. java.lang.InterruptedException occuers
      6. restart EAP without byteman code " throw new java.io.InterruptedIOException()" from the above rule.
      onMessage will be rollbacked by maxretry-counts and the message send to DLQ. (I think this is expected behavior)

      Show
      Test scenario: 1. onMessage run in MDB 2. onMessage sleep in TX timeout 3. rollback start 4. Insert the code using Byteman ------------- RULE rollback2 CLASS org.apache.activemq.transport.WireFormatNegotiator METHOD oneway(Object) AT ENTRY IF $1.toString().startsWith("MessageAck") DO traceln("*****************" + $1.toString()); throw new java.io.InterruptedIOException() ENDRULE ------------- 5. java.lang.InterruptedException occuers 6. restart EAP without byteman code " throw new java.io.InterruptedIOException()" from the above rule. onMessage will be rollbacked by maxretry-counts and the message send to DLQ. (I think this is expected behavior)

      We have a case where the transaction in JBoss EAP transaction rollback failed, and there is a stacktrace, and we don't know what cause it but this failure of rollback cause EAP transaction roll into a doubt state and the message is stuck until we restart the EAP.
      We checked with EAP Transaction experts and they suggests the ActiveMQ should retry the rollback.[2]
      2015-08-19 10:17:03,827 WARN[com.arjuna.ats.arjuna](Transaction Reaper) ARJUNA012117: TransactionReaper::check timeout for TX 0:ffff650182a8:58549259:55d38674:22df0 in state RUN
      2015-08-19 10:17:04,065 WARN[com.arjuna.ats.arjuna](Transaction Reaper) ARJUNA012117: TransactionReaper::check timeout for TX 0:ffff650182a8:58549259:55d38674:22dec in state CANCEL
      2015-08-19 10:17:04,328 WARN[com.arjuna.ats.arjuna](Transaction Reaper) ARJUNA012117: TransactionReaper::check timeout for TX 0:ffff650182a8:58549259:55d38674:22df0 in state SCHEDULE_CANCEL
      2015-08-19 10:17:04,488 WARN[com.arjuna.ats.jta](Transaction Reaper Worker 0) ARJUNA016045: attempted rollback of < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff650182a8:58549259:55d38674:22dec, node_name=1, branch_uid=0:ffff650182a8:58549259:55d38674:22ded, subordinatenodename=null, eis_name=unknown eis name > (org.apache.activemq.ra.LocalAndXATransaction@3de1f429) failed with exception code XAException.XAER_RMFAIL: javax.transaction.xa.XAException: java.io.InterruptedIOException
      at org.apache.activemq.TransactionContext.toXAException(TransactionContext.java:805)
      at org.apache.activemq.TransactionContext.rollback(TransactionContext.java:532)
      at org.apache.activemq.ra.LocalAndXATransaction.rollback(LocalAndXATransaction.java:141)
      at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelAbort(XAResourceRecord.java:358)[jbossjts-jacorb-4.17.7.Final-redhat-4-bz-1023562.jar:4.17.7.Final-redhat-1]
      at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:2853)[jbossjts-jacorb-4.17.7.Final-redhat-4-bz-1023562.jar:4.17.7.Final-redhat-1]
      at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:2832)[jbossjts-jacorb-4.17.7.Final-redhat-4-bz-1023562.jar:4.17.7.Final-redhat-1]
      at com.arjuna.ats.arjuna.coordinator.BasicAction.Abort(BasicAction.java:1625)[jbossjts-jacorb-4.17.7.Final-redhat-4-bz-1023562.jar:4.17.7.Final-redhat-1]
      at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.cancel(TwoPhaseCoordinator.java:118)[jbossjts-jacorb-4.17.7.Final-redhat-4-bz-1023562.jar:4.17.7.Final-redhat-1]
      at com.arjuna.ats.arjuna.AtomicAction.cancel(AtomicAction.java:215)[jbossjts-jacorb-4.17.7.Final-redhat-4-bz-1023562.jar:4.17.7.Final-redhat-1]
      at com.arjuna.ats.arjuna.coordinator.TransactionReaper.doCancellations(TransactionReaper.java:370)[jbossjts-jacorb-4.17.7.Final-redhat-4-bz-1023562.jar:4.17.7.Final-redhat-1]
      at com.arjuna.ats.internal.arjuna.coordinator.ReaperWorkerThread.run(ReaperWorkerThread.java:78)[jbossjts-jacorb-4.17.7.Final-redhat-4-bz-1023562.jar:4.17.7.Final-redhat-1]
      Caused by: javax.jms.JMSException: java.io.InterruptedIOException
      at org.apache.activemq.util.JMSExceptionSupport.create(JMSExceptionSupport.java:72)
      at org.apache.activemq.ActiveMQConnection.doAsyncSendPacket(ActiveMQConnection.java:1323)
      at org.apache.activemq.ActiveMQConnection.asyncSendPacket(ActiveMQConnection.java:1315)
      at org.apache.activemq.ActiveMQSession.asyncSendPacket(ActiveMQSession.java:1972)
      at org.apache.activemq.ActiveMQSession$5.afterRollback(ActiveMQSession.java:948)
      at org.apache.activemq.TransactionContext.afterRollback(TransactionContext.java:161)
      at org.apache.activemq.TransactionContext.rollback(TransactionContext.java:527)
      ... 9 more
      Caused by: java.io.InterruptedIOException
      at org.apache.activemq.transport.WireFormatNegotiator.oneway(WireFormatNegotiator.java:102)
      at org.apache.activemq.transport.MutexTransport.oneway(MutexTransport.java:68)
      at org.apache.activemq.transport.ResponseCorrelator.oneway(ResponseCorrelator.java:60)
      at org.apache.activemq.ActiveMQConnection.doAsyncSendPacket(ActiveMQConnection.java:1321)
      ... 14 more2015-08-19 10:17:04,493 WARN[com.arjuna.ats.arjuna](Transaction Reaper Worker 0) ARJUNA012091: Top-level abort of action 0:ffff650182a8:58549259:55d38674:22dec received TwoPhaseOutcome.FINISH_ERROR from com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord
      2015-08-19 10:17:15,361 WARN[com.arjuna.ats.arjuna](default-threads - 46) ARJUNA012077: Abort called on already aborted atomic action 0:ffff650182a8:58549259:55d38674:22dec
      2015-08-19 10:17:15,363 INFO[org.apache.activemq.ra.ServerSessionImpl:1](default-threads - 46) Endpoint ActiveMQSession

      {id=ID:mh1ce005-58208-1439925878652-93:1:1,started=true}

      failed to process message. Reason: Endpoint after delivery notification failure: javax.resource.spi.LocalTransactionException: javax.transaction.RollbackException: ARJUNA016102: The transaction is not active! Uid is 0:ffff650182a8:58549259:55d38674:22dec

        1. reproducer.zip
          54 kB

              gtully@redhat.com Gary Tully
              rhn-support-whui Roger Hui
              Petra Svobodova Petra Svobodova (Inactive)
              Votes:
              0 Vote for this issue
              Watchers:
              10 Start watching this issue

                Created:
                Updated:
                Resolved: