środa, kwietnia 30, 2014

Case when EMS FT cluster doesn't have XA state propagation between nodes

final Tibemsd ems1a = new Tibemsd("ems1", "C:/tibco/ems/8.0/bin/tibemsd.exe",
"C:/tibco/TIBCO_HOME/tibco/cfgmgmt/ems/data/tibemsd1.conf");
final Tibemsd ems1p = new Tibemsd("ems2", "C:/tibco/ems/8.0/bin/tibemsd.exe",
"C:/tibco/TIBCO_HOME/tibco/cfgmgmt/ems/data/tibemsd2.conf");

ems1a.shutdownIfEnabled("admin", "Adm1n");
ems1p.shutdownIfEnabled("admin", "Adm1n");

ems1a.start("admin", "Adm1n");
Thread.sleep(10000);
ems1p.start("admin", "Adm1n");
ems1a.waitForActive(180000);
ems1a.fillQueue("test.fw1", "0", 1000);
ems1a.fillQueue("test.bw1", "0", 1000);

XAContext push = ems1a.createXAContext(ems1p);
push.setTimeout(600000);

try {
Message m = push.receiveFrom("test.fw1", 1000);
push.sleep(10000);
ems1a.kill();
ems1p.waitForActive(180000);
push.sendTo(m, "test.bw1");
push.finish(true);
}
catch (Exception e) {
System.err.println("\n/****\n"+Logger.describeError("BAD THING (TM)", e)+"***/");
try {
push.finish(false);
}
catch (Exception exc) {
exc.printStackTrace();
}
}

int c1f = ems1p.countQueueByConsuming("test.fw1");
int c1b = ems1p.countQueueByConsuming("test.bw1");
ems1p.kill();
String results[] = { "ems1p.test.fw1", c1f+"", "ems1p.test.bw1", c1b+"" };
for (String r : results)
System.err.print(r+", ");
assertThat("count(ems1p.test.fw1) == count(ems1p.test.bw1)", c1f, equalTo(c1b));
assertThat("count(ems1p.test.fw1) == 100", c1f, equalTo(1000));

---
[ems1]
[ems1] TIBCO Enterprise Message Service.
[ems1] Copyright 2003-2013 by TIBCO Software Inc.
[ems1] All rights reserved.
[ems1]
[ems1] Version 8.0.0 V9 6/7/2013
[ems1]
[ems1] 2014-04-30 17:11:24.375 Process started from 'C:\tibco\ems\8.0\bin\tibemsd.exe'.
[ems1] 2014-04-30 17:11:24.375 Process Id: 5988
[ems1] 2014-04-30 17:11:24.375 Hostname: localhost
[ems1] 2014-04-30 17:11:24.375 Hostname IP address: [fe80::9550:65b9:f97:8d4e%27]
[ems1] 2014-04-30 17:11:24.375 Hostname IP address: 192.168.27.1
[ems1] 2014-04-30 17:11:24.375 Reading configuration from 'C:/tibco/TIBCO_HOME/tibco/cfgmgmt/ems/data/tibemsd1.conf'.
[ems1] 2014-04-30 17:11:24.378 Logging into file 'C:/tibco/TIBCO_HOME/tibco/cfgmgmt/ems/data/datastore/logfile'
[ems1] 2014-04-30 17:11:24.379 Server name: 'EMS-SERVER-DC2'.
[ems1] 2014-04-30 17:11:24.379 Storage Location: 'C:/tibco/TIBCO_HOME/tibco/cfgmgmt/ems/data/datastore'.
[ems1] 2014-04-30 17:11:24.379 Routing is enabled.
[ems1] 2014-04-30 17:11:24.379 Authorization is disabled.
[ems1] 2014-04-30 17:11:28.368 Active server 'tcp://localhost:8222' not found.
[ems1] 2014-04-30 17:11:28.368 Continuing as active server.
[ems1] 2014-04-30 17:11:28.372 Accepting connections on tcp://[::]:7222.
[ems1] 2014-04-30 17:11:28.372 Accepting connections on tcp://0.0.0.0:7222.
[ems1] 2014-04-30 17:11:28.372 Recovering state, please wait.
[ems2]
[ems2] TIBCO Enterprise Message Service.
[ems2] Copyright 2003-2013 by TIBCO Software Inc.
[ems2] All rights reserved.
[ems2]
[ems2] Version 8.0.0 V9 6/7/2013
[ems2]
[ems2] 2014-04-30 17:11:34.348 Process started from 'C:\tibco\ems\8.0\bin\tibemsd.exe'.
[ems2] 2014-04-30 17:11:34.348 Process Id: 2928
[ems2] 2014-04-30 17:11:34.348 Hostname: localhost
[ems2] 2014-04-30 17:11:34.348 Hostname IP address: [fe80::9550:65b9:f97:8d4e%27]
[ems2] 2014-04-30 17:11:34.348 Hostname IP address: 192.168.27.1
[ems2] 2014-04-30 17:11:34.348 Reading configuration from 'C:/tibco/TIBCO_HOME/tibco/cfgmgmt/ems/data/tibemsd2.conf'.
[ems2] 2014-04-30 17:11:34.351 Logging into file 'C:/tibco/TIBCO_HOME/tibco/cfgmgmt/ems/data/datastore/logfile'
[ems2] 2014-04-30 17:11:34.352 Server name: 'EMS-SERVER-DC2'.
[ems2] 2014-04-30 17:11:34.352 Storage Location: 'C:/tibco/TIBCO_HOME/tibco/cfgmgmt/ems/data/datastore'.
[ems2] 2014-04-30 17:11:34.352 Routing is enabled.
[ems2] 2014-04-30 17:11:34.352 Authorization is disabled.
[ems1] ...
[ems1] 2014-04-30 17:11:36.647 Recovered 1001 messages.
[ems1] 2014-04-30 17:11:36.647 Server is active.
[ems1] 2014-04-30 17:11:36.649 Backup server 'EMS-SERVER-DC2@localhost' has connected.
[ems2] 2014-04-30 17:11:36.654 Accepting connections on tcp://[::]:8222.
[ems2] 2014-04-30 17:11:36.654 Accepting connections on tcp://0.0.0.0:8222.
[ems2] 2014-04-30 17:11:36.654 Server is in standby mode for 'tcp://localhost:7222'.
[ems1] is active
[ems1] fillQueue(test.fw1) > counting messages
[ems1] fillQueue(test.fw1) > will start from 0
[ems1] fillQueue(test.fw1) > adjusting
[ems1] fillQueue(test.bw1) > counting messages
[ems1] fillQueue(test.bw1) > will start from 0
[ems1] fillQueue(test.bw1) > adjusting
[ems2] 2014-04-30 17:11:37.600 [admin@localhost]: connect failed: server in standby mode
[2014-04-30 17:11:38.678 Thread[main,5,main]] Successfully connected to tcp://7222
[XARES] start in tcp://7222,tcp://8222 #1
[TX tcp://7222,tcp://8222] receive from test.fw1
[ems1] killed
[ems2] 2014-04-30 17:11:48.961 Connection to primary server 'tcp://localhost:7222' has been lost.
[ems2] 2014-04-30 17:11:48.961 Server activating on failure of 'tcp://localhost:7222'.
[ems2] 2014-04-30 17:11:48.961 Server rereading configuration.
[ems2] 2014-04-30 17:11:48.963 Recovering state, please wait.
[ems2] ...
[ems2] 2014-04-30 17:11:57.474 Recovered 2002 messages.
[ems2] 2014-04-30 17:11:57.474 Server is now active.
[2014-04-30 17:11:57.585 Thread[Thread-132,5,main]] Cannot connect to tcp://7222: Connection is being closed
[ems2] is active
[TX tcp://7222,tcp://8222] send to test.bw1
[2014-04-30 17:12:17.890 Thread[main,5,main]] Successfully connected to tcp://8222

/****
BAD THING (TM): javax.jms.IllegalStateException: Session is closed
at com.tibco.tibjms.TibjmsxSessionImp.createQueue(TibjmsxSessionImp.java:5030)
at com.tibco.tibjms.TibjmsQueueSession.createQueue(TibjmsQueueSession.java:60)
at com.tibco.tibjms.TibjmsXAQueueSession.createQueue(TibjmsXAQueueSession.java:17)
at com.tibco.tibjms.TibemsXAUniSession$18.execute(TibemsXAUniSession.java:325)
at com.tibco.tibjms.TibemsXAUniSession.execute(TibemsXAUniSession.java:115)
at com.tibco.tibjms.TibemsXAUniSession.createQueue(TibemsXAUniSession.java:322)
at ems.qa.XAContext.sendTo(XAContext.java:89)
at ems.qa.tests.SimpleJmsMove2.testXAWithMovingMessageBetweenQueues(SimpleJmsMove2.java:50)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:601)
at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47)
at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44)
at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:271)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:70)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)
at org.junit.runners.ParentRunner.run(ParentRunner.java:309)
at org.eclipse.jdt.internal.junit4.runner.JUnit4TestReference.run(JUnit4TestReference.java:50)
at org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:38)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:467)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:683)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:390)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:197)
***/
[TX tcp://7222,tcp://8222] rollback
[XARES] end in tcp://7222,tcp://8222 #1
[ems2] 2014-04-30 17:12:17.892 ERROR: Cannot find transaction referred to in xa end request. connID=3 sessID=5 {formatID=131075 gtrid_length=51 bqual_length=25 data=-3f57e4ff:c62f:536112aa:0--3f57e4ff:c62f:536112aa:3-3f57e4ff:c62f:536112aa:4}

/****
[XARES] end failed in tcp://7222,tcp://8222 #1, error 103: javax.transaction.xa.XAException
at com.tibco.tibjms.TibemsXAResource.end(TibemsXAResource.java:42)
at ems.qa.XAResourceWrapper.end(XAResourceWrapper.java:50)
at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelAbort(XAResourceRecord.java:396)
at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3270)
at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3248)
at com.arjuna.ats.arjuna.coordinator.BasicAction.Abort(BasicAction.java:1933)
at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.cancel(TwoPhaseCoordinator.java:114)
at com.arjuna.ats.arjuna.AtomicAction.abort(AtomicAction.java:201)
at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.rollbackAndDisassociate(TransactionImple.java:1497)
at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.rollback(BaseTransaction.java:165)
at ems.qa.XAContext.finish(XAContext.java:58)
at ems.qa.tests.SimpleJmsMove2.testXAWithMovingMessageBetweenQueues(SimpleJmsMove2.java:56)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:601)
at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47)
at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44)
at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:271)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:70)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)
at org.junit.runners.ParentRunner.run(ParentRunner.java:309)
at org.eclipse.jdt.internal.junit4.runner.JUnit4TestReference.run(JUnit4TestReference.java:50)
at org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:38)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:467)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:683)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:390)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:197)
***/
[XARES] rollback in tcp://7222,tcp://8222 #1
[ems2] 2014-04-30 17:12:18.002 ERROR: Cannot find transaction referred to in xa rollback request. connID=3 {formatID=131075 gtrid_length=51 bqual_length=25 data=-3f57e4ff:c62f:536112aa:0--3f57e4ff:c62f:536112aa:3-3f57e4ff:c62f:536112aa:4}

/****
[XARES] rollback failed in tcp://7222,tcp://8222 #1, error 103: javax.transaction.xa.XAException
at com.tibco.tibjms.TibemsXAResource.rollback(TibemsXAResource.java:87)
at ems.qa.XAResourceWrapper.rollback(XAResourceWrapper.java:98)
at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelAbort(XAResourceRecord.java:420)
at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3270)
at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3248)
at com.arjuna.ats.arjuna.coordinator.BasicAction.Abort(BasicAction.java:1933)
at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.cancel(TwoPhaseCoordinator.java:114)
at com.arjuna.ats.arjuna.AtomicAction.abort(AtomicAction.java:201)
at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.rollbackAndDisassociate(TransactionImple.java:1497)
at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.rollback(BaseTransaction.java:165)
at ems.qa.XAContext.finish(XAContext.java:58)
at ems.qa.tests.SimpleJmsMove2.testXAWithMovingMessageBetweenQueues(SimpleJmsMove2.java:56)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:601)
at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47)
at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44)
at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:271)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:70)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)
at org.junit.runners.ParentRunner.run(ParentRunner.java:309)
at org.eclipse.jdt.internal.junit4.runner.JUnit4TestReference.run(JUnit4TestReference.java:50)
at org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:38)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:467)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:683)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:390)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:197)
***/
[ems2] killed
ems1p.test.fw1, 1000, ems1p.test.bw1, 1000,

0 komentarze: