activemq-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Hubert Cabot (JIRA)" <j...@apache.org>
Subject [jira] [Created] (AMQ-6525) Two-phase commit fails if broker restarts
Date Mon, 05 Dec 2016 15:29:58 GMT
Hubert Cabot created AMQ-6525:
---------------------------------

             Summary: Two-phase commit fails if broker restarts
                 Key: AMQ-6525
                 URL: https://issues.apache.org/jira/browse/AMQ-6525
             Project: ActiveMQ
          Issue Type: Bug
    Affects Versions: 5.14.1
            Reporter: Hubert Cabot


When using the attached code, and restarting the broker during the Thread.sleep on line 38,
we obtain the following stack trace and no message is present in the queue afterwards:
{code:title=FailoverXATest.java}
package com.example.test.failover;

import org.apache.activemq.ActiveMQXAConnectionFactory;
import org.junit.Test;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import javax.jms.*;
import javax.transaction.xa.XAResource;
import javax.transaction.xa.Xid;
import java.io.ByteArrayOutputStream;
import java.io.DataOutputStream;
import java.io.IOException;
import java.util.concurrent.atomic.AtomicLong;


public class FailoverXATest {

    private static final Logger LOG = LoggerFactory.getLogger(FailoverXATest.class);
    private static final String URL = "tcp://localhost:61616";
    private static final String QUEUE_NAME = "Failover.WithXaTx";
    private static AtomicLong txGenerator = new AtomicLong(System.currentTimeMillis());

    @Test
    public void failoverXABrokerRestartTest() throws Exception{
        String url = "failover://(" + URL + ")";
        ActiveMQXAConnectionFactory cf = new ActiveMQXAConnectionFactory(url);
        XAConnection connection = cf.createXAConnection();
        connection.start();
        final XASession session = connection.createXASession();
        Queue destination = session.createQueue(QUEUE_NAME);

        Xid xid = createXid();
        session.getXAResource().start(xid, XAResource.TMNOFLAGS);
        produceMessage(session, destination);
        session.getXAResource().end(xid, XAResource.TMSUCCESS);
        LOG.info("Message sent, waiting 70s during which AMQ will be restarted");
        Thread.sleep(70000);
        LOG.info("Done waiting");

        try {
            session.getXAResource().prepare(xid);
        } catch (Exception expected) {
            LOG.error("Error on prepare", expected);
        }
        try {
            session.getXAResource().commit(xid, false);
        } catch (Exception expected) {
            LOG.error("Error on commit" ,expected);
        }

        connection.close();
    }

    private void produceMessage(final Session producerSession, Queue destination) throws Exception
{
        MessageProducer producer = producerSession.createProducer(destination);
        TextMessage message = producerSession.createTextMessage("Test message");
        producer.send(message);
        producer.close();
    }

    private Xid createXid() throws IOException {

        ByteArrayOutputStream byteArrayOS = new ByteArrayOutputStream();
        DataOutputStream os = new DataOutputStream(byteArrayOS);
        os.writeLong(txGenerator.incrementAndGet());
        os.close();
        final byte[] bs = byteArrayOS.toByteArray();

        return new Xid() {
            public int getFormatId() {
                return 86;
            }

            public byte[] getGlobalTransactionId() {
                return bs;
            }

            public byte[] getBranchQualifier() {
                return bs;
            }
        };
    }
}

{code}

{code:title=Client logs}
"C:\Program Files\Java\jdk1.8.0_45\bin\java" -Didea.launcher.port=7533 "-Didea.launcher.bin.path=C:\Program
Files (x86)\JetBrains\IntelliJ IDEA Community Edition 2016.3\bin" -Dfile.encoding=UTF-8 -classpath
"C:\Program Files (x86)\JetBrains\IntelliJ IDEA Community Edition 2016.3\lib\idea_rt.jar;C:\Program
Files (x86)\JetBrains\IntelliJ IDEA Community Edition 2016.3\plugins\junit\lib\junit-rt.jar;C:\Program
Files\Java\jdk1.8.0_45\jre\lib\charsets.jar;C:\Program Files\Java\jdk1.8.0_45\jre\lib\deploy.jar;C:\Program
Files\Java\jdk1.8.0_45\jre\lib\ext\access-bridge-64.jar;C:\Program Files\Java\jdk1.8.0_45\jre\lib\ext\cldrdata.jar;C:\Program
Files\Java\jdk1.8.0_45\jre\lib\ext\dnsns.jar;C:\Program Files\Java\jdk1.8.0_45\jre\lib\ext\jaccess.jar;C:\Program
Files\Java\jdk1.8.0_45\jre\lib\ext\jfxrt.jar;C:\Program Files\Java\jdk1.8.0_45\jre\lib\ext\localedata.jar;C:\Program
Files\Java\jdk1.8.0_45\jre\lib\ext\nashorn.jar;C:\Program Files\Java\jdk1.8.0_45\jre\lib\ext\sunec.jar;C:\Program
Files\Java\jdk1.8.0_45\jre\lib\ext\sunjce_provider.jar;C:\Program Files\Java\jdk1.8.0_45\jre\lib\ext\sunmscapi.jar;C:\Program
Files\Java\jdk1.8.0_45\jre\lib\ext\sunpkcs11.jar;C:\Program Files\Java\jdk1.8.0_45\jre\lib\ext\zipfs.jar;C:\Program
Files\Java\jdk1.8.0_45\jre\lib\javaws.jar;C:\Program Files\Java\jdk1.8.0_45\jre\lib\jce.jar;C:\Program
Files\Java\jdk1.8.0_45\jre\lib\jfr.jar;C:\Program Files\Java\jdk1.8.0_45\jre\lib\jfxswt.jar;C:\Program
Files\Java\jdk1.8.0_45\jre\lib\jsse.jar;C:\Program Files\Java\jdk1.8.0_45\jre\lib\management-agent.jar;C:\Program
Files\Java\jdk1.8.0_45\jre\lib\plugin.jar;C:\Program Files\Java\jdk1.8.0_45\jre\lib\resources.jar;C:\Program
Files\Java\jdk1.8.0_45\jre\lib\rt.jar;C:\Utilisateurs\hubert\Documents\Java Projects\IntelliJProjects\JMS-AMQ-XA\target\test-classes;C:\Utilisateurs\hubert\Documents\Java
Projects\IntelliJProjects\JMS-AMQ-XA\target\classes;C:\Utilisateurs\hubert\.m2\repository\org\apache\activemq\activemq-client\5.14.1\activemq-client-5.14.1.jar;C:\Utilisateurs\hubert\.m2\repository\org\apache\geronimo\specs\geronimo-jms_1.1_spec\1.1.1\geronimo-jms_1.1_spec-1.1.1.jar;C:\Utilisateurs\hubert\.m2\repository\org\fusesource\hawtbuf\hawtbuf\1.11\hawtbuf-1.11.jar;C:\Utilisateurs\hubert\.m2\repository\org\apache\geronimo\specs\geronimo-j2ee-management_1.1_spec\1.0.1\geronimo-j2ee-management_1.1_spec-1.0.1.jar;C:\Utilisateurs\hubert\.m2\repository\org\apache\activemq\activemq-broker\5.14.1\activemq-broker-5.14.1.jar;C:\Utilisateurs\hubert\.m2\repository\org\apache\activemq\activemq-openwire-legacy\5.14.1\activemq-openwire-legacy-5.14.1.jar;C:\Utilisateurs\hubert\.m2\repository\org\apache\activemq\activemq-kahadb-store\5.14.1\activemq-kahadb-store-5.14.1.jar;C:\Utilisateurs\hubert\.m2\repository\org\apache\activemq\protobuf\activemq-protobuf\1.1\activemq-protobuf-1.1.jar;C:\Utilisateurs\hubert\.m2\repository\commons-net\commons-net\3.5\commons-net-3.5.jar;C:\Utilisateurs\hubert\.m2\repository\javax\transaction\jta\1.1\jta-1.1.jar;C:\Utilisateurs\hubert\.m2\repository\junit\junit\4.12\junit-4.12.jar;C:\Utilisateurs\hubert\.m2\repository\org\hamcrest\hamcrest-core\1.3\hamcrest-core-1.3.jar;C:\Utilisateurs\hubert\.m2\repository\org\apache\logging\log4j\log4j-core\2.7\log4j-core-2.7.jar;C:\Utilisateurs\hubert\.m2\repository\org\apache\logging\log4j\log4j-api\2.7\log4j-api-2.7.jar;C:\Utilisateurs\hubert\.m2\repository\org\slf4j\slf4j-log4j12\1.7.21\slf4j-log4j12-1.7.21.jar;C:\Utilisateurs\hubert\.m2\repository\log4j\log4j\1.2.17\log4j-1.2.17.jar;C:\Utilisateurs\hubert\.m2\repository\org\slf4j\slf4j-api\1.7.21\slf4j-api-1.7.21.jar"
com.intellij.rt.execution.application.AppMain com.intellij.rt.execution.junit.JUnitStarter
-ideVersion5 com.example.test.failover.FailoverXATest
2016-12-05 16:04:36 INFO  FailoverTransport:1052 - Successfully connected to tcp://localhost:61616
2016-12-05 16:04:36 INFO  FailoverXATest:37 - Message sent, waiting 70s during which AMQ will
be restarted
2016-12-05 16:04:42 WARN  FailoverTransport:280 - Transport (tcp://localhost:61616) failed
, attempting to automatically reconnect: {}
java.io.EOFException
	at java.io.DataInputStream.readInt(DataInputStream.java:392)
	at org.apache.activemq.openwire.OpenWireFormat.unmarshal(OpenWireFormat.java:268)
	at org.apache.activemq.transport.tcp.TcpTransport.readCommand(TcpTransport.java:240)
	at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:232)
	at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:215)
	at java.lang.Thread.run(Thread.java:745)
2016-12-05 16:04:50 INFO  FailoverTransport:1054 - Successfully reconnected to tcp://localhost:61616
2016-12-05 16:05:46 INFO  FailoverXATest:39 - Done waiting
2016-12-05 16:05:46 WARN  TransactionContext:604 - commit of: XID:[86,globalId=00158ffffffcfffffff83ffffffdeffffffc2,branchId=00158ffffffcfffffff83ffffffdeffffffc2]
failed with: javax.jms.JMSException: Transaction 'XID:[86,globalId=00158ffffffcfffffff83ffffffdeffffffc2,branchId=00158ffffffcfffffff83ffffffdeffffffc2]'
has not been started. xaErrorCode:-4
javax.jms.JMSException: Transaction 'XID:[86,globalId=00158ffffffcfffffff83ffffffdeffffffc2,branchId=00158ffffffcfffffff83ffffffdeffffffc2]'
has not been started. xaErrorCode:-4
	at org.apache.activemq.util.JMSExceptionSupport.create(JMSExceptionSupport.java:54)
	at org.apache.activemq.ActiveMQConnection.syncSendPacket(ActiveMQConnection.java:1399)
	at org.apache.activemq.ActiveMQConnection.syncSendPacket(ActiveMQConnection.java:1428)
	at org.apache.activemq.TransactionContext.commit(TransactionContext.java:585)
	at com.example.test.failover.FailoverXATest.failoverXABrokerRestartTest(FailoverXATest.java:47)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:497)
	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
	at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
	at com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:68)
	at com.intellij.rt.execution.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:51)
	at com.intellij.rt.execution.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:237)
	at com.intellij.rt.execution.junit.JUnitStarter.main(JUnitStarter.java:70)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:497)
	at com.intellij.rt.execution.application.AppMain.main(AppMain.java:147)
Caused by: javax.transaction.xa.XAException: Transaction 'XID:[86,globalId=00158ffffffcfffffff83ffffffdeffffffc2,branchId=00158ffffffcfffffff83ffffffdeffffffc2]'
has not been started. xaErrorCode:-4
	at org.apache.activemq.transaction.Transaction.newXAException(Transaction.java:212)
	at org.apache.activemq.broker.TransactionBroker.getTransaction(TransactionBroker.java:351)
	at org.apache.activemq.broker.TransactionBroker.commitTransaction(TransactionBroker.java:251)
	at org.apache.activemq.broker.MutableBrokerFilter.commitTransaction(MutableBrokerFilter.java:118)
	at org.apache.activemq.broker.TransportConnection.processCommitTransactionTwoPhase(TransportConnection.java:544)
	at org.apache.activemq.command.TransactionInfo.visit(TransactionInfo.java:102)
	at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:333)
	at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:197)
	at org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
	at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:125)
	at org.apache.activemq.transport.AbstractInactivityMonitor.onCommand(AbstractInactivityMonitor.java:300)
	at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83)
	at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:233)
	at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:215)
	at java.lang.Thread.run(Thread.java:745)
2016-12-05 16:05:46 ERROR FailoverXATest:49 - Error on commit
javax.transaction.xa.XAException: Transaction 'XID:[86,globalId=00158ffffffcfffffff83ffffffdeffffffc2,branchId=00158ffffffcfffffff83ffffffdeffffffc2]'
has not been started. xaErrorCode:-4
	at org.apache.activemq.TransactionContext.toXAException(TransactionContext.java:793)
	at org.apache.activemq.TransactionContext.commit(TransactionContext.java:622)
	at com.example.test.failover.FailoverXATest.failoverXABrokerRestartTest(FailoverXATest.java:47)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:497)
	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
	at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
	at com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:68)
	at com.intellij.rt.execution.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:51)
	at com.intellij.rt.execution.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:237)
	at com.intellij.rt.execution.junit.JUnitStarter.main(JUnitStarter.java:70)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:497)
	at com.intellij.rt.execution.application.AppMain.main(AppMain.java:147)
Caused by: javax.transaction.xa.XAException: Transaction 'XID:[86,globalId=00158ffffffcfffffff83ffffffdeffffffc2,branchId=00158ffffffcfffffff83ffffffdeffffffc2]'
has not been started. xaErrorCode:-4
	at org.apache.activemq.transaction.Transaction.newXAException(Transaction.java:212)
	at org.apache.activemq.broker.TransactionBroker.getTransaction(TransactionBroker.java:351)
	at org.apache.activemq.broker.TransactionBroker.commitTransaction(TransactionBroker.java:251)
	at org.apache.activemq.broker.MutableBrokerFilter.commitTransaction(MutableBrokerFilter.java:118)
	at org.apache.activemq.broker.TransportConnection.processCommitTransactionTwoPhase(TransportConnection.java:544)
	at org.apache.activemq.command.TransactionInfo.visit(TransactionInfo.java:102)
	at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:333)
	at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:197)
	at org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
	at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:125)
	at org.apache.activemq.transport.AbstractInactivityMonitor.onCommand(AbstractInactivityMonitor.java:300)
	at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83)
	at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:233)
	at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:215)
	at java.lang.Thread.run(Thread.java:745)

Process finished with exit code 0
{code}

The client is successfully reconnected, yet the commit fails and no message is present in
the queue at the end of the test.

Client and broker versions is 5.14.1. 
Windows distribution is used for the test above.



--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Mime
View raw message