You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@activemq.apache.org by "Hubert Cabot (JIRA)" <ji...@apache.org> on 2016/12/05 15:29:58 UTC
[jira] [Created] (AMQ-6525) Two-phase commit fails if broker
restarts
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)