[mule-user] How to rollback a transaction?

19 views
Skip to first unread message

hwt

unread,
Sep 6, 2007, 6:38:54 AM9/6/07
to us...@mule.codehaus.org

Hi,

I have been writing a prototype to figure out how Mule transactions affects
my system design. The prototype has a Mule bridge component that gets a
message from an ActiveMQ JMS queue, starts a transaction, and multicasts the
message to two Derby JDBC endpoints. The two JDBC endpoints always join an
existing transaction, which should be the transaction started at the inbound
JMS queue. When the JDBC operation at one of the JDBC endpoints fails with
a unique-constraint exception, Derby shows that the JDBC operation at the
other JDBC endpoint is still committed. Isn't Mule supposed to rollback
both JDBC operations in such a situation? Or have I configured something
incorrectly?

Will greatly appreciate your help.

Hann Wei


This is the ActiveMQ connector:

<connector name="activeMQXAConnector"
className="org.mule.providers.jms.activemq.ActiveMqJmsConnector">
<properties>
<property name="persistentDelivery" value="true" />
<property name="specification" value="1.1" />
<property name="recoverJmsConnections" value="true" />
<container-property name="connectionFactory"
reference="activeMQXAConnectionFactory" />
</properties>
</connector>

Its XA connection factory is:

<bean id="activeMQXAConnectionFactory"
class="org.apache.activemq.ActiveMQXAConnectionFactory">
<property name="brokerURL" value="tcp://localhost:61616"/>
</bean>

This is the JDBC connector:

<connector name="jdbcConnector"
className="org.mule.providers.jdbc.JdbcConnector">
<properties>
<container-property name="dataSource" reference="DerbyDS" />
<map name="queries">
<property name="insertRecord2" value="INSERT into Testing1 (name, value)
VALUES (${payload},${now})" />
<property name="insertRecord1" value="INSERT into Testing2 (name) VALUES
(${payload})" />
</map>
</properties>
<exception-strategy
className="com.mansion.integration.esl.mule.TransactionRollbackExceptionStrategy">
</exception-strategy>
</connector>

TransactionRollbackExceptionStrategy forces a rollback when an exception is
caught:

protected void defaultHandler (Throwable exception)
{
markTransactionForRollback ();
super.defaultHandler (exception);
}

And this is the XA Derby datasource:

<bean id="DerbyDS" class="org.enhydra.jdbc.standard.StandardXADataSource"
destroy-method="shutdown">
<property
name="driverName"><value>net.sf.log4jdbc.DriverSpy</value></property>
<property
name="url"><value>jdbc:log4jdbc:derby://localhost:1527/firstdb</value></property>
</bean>

This is the Mule bridge component that gets a message from an XA ActiveMQ
queue, and sends it to two XA JDBC endpoints:

<mule-descriptor name="TestJdbcUMO1"
implementation="org.mule.components.simple.BridgeComponent">
<inbound-router>
<endpoint address="jms://esl/transactionQueue"
connector="activeMQXAConnector" transformers="JMSToObjectTransformer">
<transaction action="ALWAYS_BEGIN"
factory="org.mule.transaction.XaTransactionFactory"/>
</endpoint>
</inbound-router>
<outbound-router>
<router className="org.mule.routing.outbound.MulticastingRouter">
<endpoint address="jdbc://insertRecord1"
connector="jdbcConnector">
<transaction action="ALWAYS_JOIN"
factory="org.mule.transaction.XaTransactionFactory"/>
</endpoint>
<endpoint address="jdbc://insertRecord2"
connector="jdbcConnector">
<transaction action="ALWAYS_JOIN"
factory="org.mule.transaction.XaTransactionFactory"/>
</endpoint>
<transaction action="ALWAYS_JOIN"
factory="org.mule.transaction.XaTransactionFactory"/>
</router>
</outbound-router>
</mule-descriptor>

A normal message results in two successful JDBC operations:

INFO 2007-09-06 18:00:38,635 [activeMQXAConnector.scheduler.1] jdbc.audit:
2. C
onnection.prepareStatement(INSERT into Testing2 (name) VALUES (?)) returned
net.
sf.log4jdbc.PreparedStatementSpy@144b18f
INFO 2007-09-06 18:00:38,635 [activeMQXAConnector.scheduler.1] jdbc.audit:
2. P
reparedStatement.setObject(1, abc 322) returned
INFO 2007-09-06 18:00:38,635 [activeMQXAConnector.scheduler.1]
jdbc.sqlonly: IN
SERT into Testing2 (name) VALUES ('abc 322')
INFO 2007-09-06 18:00:38,635 [activeMQXAConnector.scheduler.1]
jdbc.sqltiming:
INSERT into Testing2 (name) VALUES ('abc 322') {executed in 0 msec}
INFO 2007-09-06 18:00:38,635 [activeMQXAConnector.scheduler.1] jdbc.audit:
2. P
reparedStatement.executeUpdate() returned 1
INFO 2007-09-06 18:00:38,635 [activeMQXAConnector.scheduler.1] jdbc.audit:
2. P
reparedStatement.close() returned
INFO 2007-09-06 18:00:38,635 [activeMQXAConnector.scheduler.1] jdbc.audit:
2. C
onnection.prepareStatement(INSERT into Testing1 (name, value) VALUES (?,?))
retu
rned net.sf.log4jdbc.PreparedStatementSpy@1f1680f
INFO 2007-09-06 18:00:38,635 [activeMQXAConnector.scheduler.1] jdbc.audit:
2. P
reparedStatement.setObject(1, abc 322) returned
INFO 2007-09-06 18:00:38,635 [activeMQXAConnector.scheduler.1] jdbc.audit:
2. P
reparedStatement.setObject(2, 2007-09-06 18:00:38.635) returned
INFO 2007-09-06 18:00:38,635 [activeMQXAConnector.scheduler.1]
jdbc.sqlonly: IN
SERT into Testing1 (name, value) VALUES ('abc 322',2007-09-06 18:00:38.635)
INFO 2007-09-06 18:00:38,635 [activeMQXAConnector.scheduler.1]
jdbc.sqltiming:
INSERT into Testing1 (name, value) VALUES ('abc 322',2007-09-06
18:00:38.635) {
executed in 0 msec}
INFO 2007-09-06 18:00:38,635 [activeMQXAConnector.scheduler.1] jdbc.audit:
2. P
reparedStatement.executeUpdate() returned 1
INFO 2007-09-06 18:00:38,635 [activeMQXAConnector.scheduler.1] jdbc.audit:
2. P
reparedStatement.close() returned

However, a unique-constraint exception at one JDBC endpoint somehow cannot
cause the other JDBC operations to be rolled-back:

}}
INFO 2007-09-06 18:30:13,088 [activeMQXAConnector.scheduler.1] jdbc.audit:
8. C
onnection.prepareStatement(INSERT into Testing2 (name) VALUES (?)) returned
net.
sf.log4jdbc.PreparedStatementSpy@c7e8a7
INFO 2007-09-06 18:30:13,088 [activeMQXAConnector.scheduler.1] jdbc.audit:
8. P
reparedStatement.setObject(1, abc 322) returned
INFO 2007-09-06 18:30:13,088 [activeMQXAConnector.scheduler.1]
jdbc.sqlonly: IN
SERT into Testing2 (name) VALUES ('abc 322')
INFO 2007-09-06 18:30:13,088 [activeMQXAConnector.scheduler.1]
jdbc.sqltiming:
INSERT into Testing2 (name) VALUES ('abc 322') {executed in 0 msec}
INFO 2007-09-06 18:30:13,088 [activeMQXAConnector.scheduler.1] jdbc.audit:
8. P
reparedStatement.executeUpdate() returned 1
INFO 2007-09-06 18:30:13,088 [activeMQXAConnector.scheduler.1] jdbc.audit:
8. P
reparedStatement.close() returned
INFO 2007-09-06 18:30:13,088 [activeMQXAConnector.scheduler.1]
org.mule.provide
rs.jdbc.JdbcMessageDispatcher: Connected: JdbcMessageDispatcher{this=7b4703,
end
point=jdbc://insertRecord2}
INFO 2007-09-06 18:30:13,088 [activeMQXAConnector.scheduler.1] jdbc.audit:
8. C
onnection.prepareStatement(INSERT into Testing1 (name, value) VALUES (?,?))
retu
rned net.sf.log4jdbc.PreparedStatementSpy@1071521
INFO 2007-09-06 18:30:13,088 [activeMQXAConnector.scheduler.1] jdbc.audit:
8. P
reparedStatement.setObject(1, abc 322) returned
INFO 2007-09-06 18:30:13,088 [activeMQXAConnector.scheduler.1] jdbc.audit:
8. P
reparedStatement.setObject(2, 2007-09-06 18:30:13.088) returned
INFO 2007-09-06 18:30:13,088 [activeMQXAConnector.scheduler.1]
jdbc.sqlonly: IN
SERT into Testing1 (name, value) VALUES ('abc 322',2007-09-06 18:30:13.088)
ERROR 2007-09-06 18:30:13,120 [activeMQXAConnector.scheduler.1] jdbc.audit:
8. P
reparedStatement.executeUpdate() INSERT into Testing1 (name, value) VALUES
('abc
322',2007-09-06 18:30:13.088)
java.sql.SQLException: The statement was aborted because it would have
caused a
duplicate key value in a unique or primary key constraint or unique index
identi
fied by 'SQL070904113156050' defined on 'TESTING1'.
at
org.apache.derby.client.am.SQLExceptionFactory.getSQLException(Unknow
n Source)
at org.apache.derby.client.am.SqlException.getSQLException(Unknown
Sourc
e)
at
org.apache.derby.client.am.PreparedStatement.executeUpdate(Unknown So
urce)

I attempted to turn the JOTM logs on with these settings in
log4j.properties, but somehow no JOTM-related entries appear in the log.
Does it mean transactions have not been configured correctly for them to
work properly (that is, to do rollbacks when necessary)?

log4j.rootLogger=DEBUG, TRACE, stdout, logfile
log4j.logger.org.apache.activemq.spring=WARN
log4j.logger.org.springframework=WARN
log4j.logger.org.apache.xbean.spring=WARN
log4j.logger.org=WARN
log4j.logger.com.mansion=INFO
log4j.logger.jdbc.audit=INFO,jdbc
log4j.logger.jdbc.resultset=DEBUG,INFO,ERROR
log4j.logger.org.objectweb.jotm=DEBUG,WARN,INFO,Requests
log4j.additivity.org.objectweb.jotm=true
log4j.logger.org.objectweb.jotm.jta=DEBUG,WARN,INFO,Requests
log4j.additivity.org.objectweb.jotm.jta=true
log4j.logger.org.objectweb.jotm.recovery=DEBUG,WARN,INFO,Requests
log4j.logger.org.objectweb.jotm.tests=DEBUG,WARN,INFO,Requests
log4j.logger.org.objectweb.transaction.jta=DEBUG,WARN,INFO,Requests
log4j.additivity.org.objectweb.transaction.jta=true
log4j.logger.org.objectweb.jotm.ots=DEBUG,WARN,INFO,Requests

# When debugging or reporting problems to the ActiveMQ team,
# comment out the above lines and uncomment the next.
#log4j.rootLogger=DEBUG, out, stdout

# CONSOLE appender not used by default
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%d{HH:mm:ss,SSS} %-5p
%-20.20c [%-7.7t]: %m%n
log4j.appender.stdout.threshold=DEBUG

These are the committed entries in Derby:

[Table named Testing1]
abc 321
|2007-09-06 18:00:32.854
abc 322
|2007-09-06 18:00:38.635

[Table named Testing2]
abc 321
abc 322
abc 322
abc 322
abc 322
abc 322
abc 322
abc 322
abc 322

If rollbacks are done correctly, the number of rows in Testing2 should be
the same as the number of rows in Testing1, because the insertions of one
row to each table are done in a single transaction started at the inbound
JMS endpoint.


--
View this message in context: http://www.nabble.com/How-to-rollback-a-transaction--tf4391166.html#a12519641
Sent from the Mule - User mailing list archive at Nabble.com.


---------------------------------------------------------------------
To unsubscribe from this list please visit:

http://xircles.codehaus.org/manage_email

Dmitry

unread,
Sep 6, 2007, 8:51:27 AM9/6/07
to us...@mule.codehaus.org

Is it possible that autocommit is on on your jdbc connection? If so it's
impossible to roll already changed data back.

Dmitry


hwt wrote:
>
> Hi,
>
> I have been writing a prototype with Mule 1.4.1 to figure out how Mule
> transactions affect my system design. The prototype has a Mule bridge


> component that gets a message from an ActiveMQ JMS queue, starts a
> transaction, and multicasts the message to two Derby JDBC endpoints. The
> two JDBC endpoints always join an existing transaction, which should be
> the transaction started at the inbound JMS queue. When the JDBC operation
> at one of the JDBC endpoints fails with a unique-constraint exception,

> Derby shows that the operation at the other JDBC endpoint is still

> Does it mean the transaction manager has not been configured correctly for
> it to work properly (that is, to do rollbacks when necessary)?

--
View this message in context: http://www.nabble.com/How-to-rollback-a-transaction--tf4391166.html#a12521930

hwt

unread,
Sep 7, 2007, 2:09:42 AM9/7/07
to us...@mule.codehaus.org

Dmitry wrote:
>
> Is it possible that autocommit is on on your jdbc connection? If so it's
> impossible to roll already changed data back.
>

Thanks for the reminder. It was on. It seems there is no way to turn it
off, whether through Mule or Derby configuration. Anyway, I managed to turn
it off just now by hacking org.mule.providers.jdbc.JdbcConnector, so that
its "public Connection getConnection() throws Exception" changes to false
the value of the autoCommit attribute of the connection to be returned.
With this modification, new data never appears in the Testing1 and Testing2
tables anymore. Using a Derby client to check the table content reveals
that the tables may be locked as there is a long delay. After a while, they
are apparently unlocked, and the expected new rows do not appear.

The hacked org.mule.transaction.XaTransaction shows its doCommit() is always
executed without an exception. With autocommit turned on, the expected data
appears in the two tables, but an insertion failure does not rollback the
other insertion. With autocommit turned off, the expected data does not
appear in the two tables. Classes hacked to show execution traces reveal
that commits are always done immediately after the two insertions. However,
there are always new transactions started and rolled-back automatically
later even though no new message arrives at the Mule bridge concerned. The
rollbacks appear to have no effect when autocommit is on, but seem to result
in the "committed" insertions to be canceled.

Any idea whether or not JOTM is integrated properly with Mule 1.4.1? Are
they supposed to work with Derby for XA transactions? Is it possible that
Mule has not configured JOTM correctly to tell it to invoke
java.sql.Connection.commit() for connections involved?

Thanks.

Hann Wei
--
View this message in context: http://www.nabble.com/How-to-rollback-a-transaction--tf4391166.html#a12536499

hwt

unread,
Sep 7, 2007, 2:25:05 AM9/7/07
to us...@mule.codehaus.org

Just in case the log with autocommit turned off is needed, it is attached
below. It shows transaction bb14:38:0:01ec98354a41cd7cb6...e32001: was
committed successfully, but the tables remained locked until transaction
bb14:38:0:01ec98354a41cd7cb6...3bc002: was rolled back. And the rolling
back of the latter appears to have canceled the two insertions committed by
the former.


INFO 2007-09-07 14:15:36,291 [WrapperSimpleAppMain] org.mule.MuleManager:
**********************************************************************
* Mule ESB and Integration Platform version 1.4.1 *
* MuleSource, Inc. *
* For more information go to http://mule.mulesource.org *
* *
* Server started: 9/7/07 2:15 PM *
* Server ID: CASESL *
* JDK: 1.5.0_12 (mixed mode, sharing) *
* OS: Windows XP - Service Pack 2 (5.1, x86) *
* Host: DEVPC225 (10.234.100.65) *
* *
* Agents Running: *
* Mule Admin: accepting connections on tcp://localhost:60504 *
**********************************************************************
INFO 2007-09-07 14:15:36,291 [WrapperSimpleAppMain] org.mule.MuleServer:
Mule S
erver initialized.
Hacked TransactionCoordination::getTransaction() returning null
Hacked TransactionCoordination::getTransaction() returning null

Please enter text...:
Hacked TransactionCoordination::getTransaction() returning null
Hacked AbstractTransaction::begin() starts at
org.mule.transaction.XaTransaction

Hacked XaTransaction::doBegin() has just started
bb14:38:0:01ec98354a41cd7cb6...
e32001:
Hacked XaTransaction::doBegin() finds the transaction is of class
org.objectweb.
jotm.TransactionImpl
Hacked TransactionCoordination::bindTransaction() binding
org.mule.transaction.X
aTransaction@92b1a1
Hacked TransactionCoordination::bindTransaction() has bound
org.mule.transaction
.XaTransaction@92b1a1
Hacked AbstractTransaction::begin() ends
Hacked TransactionCoordination::getTransaction() returning
org.mule.transaction.
XaTransaction@92b1a1
abc 4444
Hacked TransactionCoordination::getTransaction() returning null
Hacked TransactionCoordination::getTransaction() returning null
INFO 2007-09-07 14:15:42,573 [SystemStreamConnector.scheduler.1]
org.mule.provi
ders.jms.JmsMessageDispatcher: Connected: JmsMessageDispatcher{this=147917a,
end
point=jms://esl/transactionQueue}
Hacked TransactionCoordination::getTransaction() returning null
Hacked TransactionCoordination::getTransaction() returning null
Hacked TransactionCoordination::getTransaction() returning null
Hacked TransactionCoordination::getTransaction() returning null
Hacked TransactionCoordination::getTransaction() returning null
************ resultMessage (1) : null
********* resultMessage (2) : null
Hacked TransactionCoordination::getTransaction() returning
org.mule.transaction.
XaTransaction@92b1a1
Hacked TransactionCoordination::getTransaction() returning
org.mule.transaction.
XaTransaction@92b1a1
Hacked TransactionCoordination::getTransaction() returning
org.mule.transaction.
XaTransaction@92b1a1
INFO 2007-09-07 14:15:42,666 [activeMQXAConnector.scheduler.1]
org.mule.provide
rs.jdbc.JdbcMessageDispatcher: Connected:
JdbcMessageDispatcher{this=14a75bb, en
dpoint=jdbc://insertRecord1}
Hacked TransactionCoordination::getTransaction() returning
org.mule.transaction.
XaTransaction@92b1a1
Hacked TransactionCoordination::getTransaction() returning
org.mule.transaction.
XaTransaction@92b1a1
INFO 2007-09-07 14:15:42,948 [activeMQXAConnector.scheduler.1] jdbc.audit:
1. C
onnection.getAutoCommit() returned true
Hacked JdbcConnector::updateAutoCommitConfig() finds the original
auto-commit va
lue is true
INFO 2007-09-07 14:15:42,948 [activeMQXAConnector.scheduler.1] jdbc.audit:
1. C
onnection.setAutoCommit(false) returned
INFO 2007-09-07 14:15:42,948 [activeMQXAConnector.scheduler.1] jdbc.audit:
1. C
onnection.getAutoCommit() returned false
Hacked JdbcConnector::updateAutoCommitConfig() finds the new auto-commit
value i
s false
INFO 2007-09-07 14:15:42,995 [activeMQXAConnector.scheduler.1] jdbc.audit:
1. C


onnection.prepareStatement(INSERT into Testing2 (name) VALUES (?)) returned
net.

sf.log4jdbc.PreparedStatementSpy@104fc23
INFO 2007-09-07 14:15:42,995 [activeMQXAConnector.scheduler.1] jdbc.audit:
1. P
reparedStatement.setObject(1, abc 4444) returned
INFO 2007-09-07 14:15:42,995 [activeMQXAConnector.scheduler.1]
jdbc.sqlonly: IN
SERT into Testing2 (name) VALUES ('abc 4444')
INFO 2007-09-07 14:15:42,995 [activeMQXAConnector.scheduler.1]
jdbc.sqltiming:
INSERT into Testing2 (name) VALUES ('abc 4444') {executed in 0 msec}
INFO 2007-09-07 14:15:42,995 [activeMQXAConnector.scheduler.1] jdbc.audit:
1. P
reparedStatement.executeUpdate() returned 1
INFO 2007-09-07 14:15:42,995 [activeMQXAConnector.scheduler.1] jdbc.audit:
1. P
reparedStatement.close() returned
Hacked TransactionCoordination::getTransaction() returning
org.mule.transaction.
XaTransaction@92b1a1
INFO 2007-09-07 14:15:42,995 [activeMQXAConnector.scheduler.1]
org.mule.provide
rs.jdbc.JdbcMessageDispatcher: Connected:
JdbcMessageDispatcher{this=15e92d7, en
dpoint=jdbc://insertRecord2}
Hacked TransactionCoordination::getTransaction() returning
org.mule.transaction.
XaTransaction@92b1a1
Hacked TransactionCoordination::getTransaction() returning
org.mule.transaction.
XaTransaction@92b1a1
INFO 2007-09-07 14:15:43,010 [activeMQXAConnector.scheduler.1] jdbc.audit:
1. C
onnection.getAutoCommit() returned false
Hacked JdbcConnector::updateAutoCommitConfig() finds the original
auto-commit va
lue is false
INFO 2007-09-07 14:15:43,010 [activeMQXAConnector.scheduler.1] jdbc.audit:
1. C
onnection.setAutoCommit(false) returned
INFO 2007-09-07 14:15:43,010 [activeMQXAConnector.scheduler.1] jdbc.audit:
1. C
onnection.getAutoCommit() returned false
Hacked JdbcConnector::updateAutoCommitConfig() finds the new auto-commit
value i
s false
INFO 2007-09-07 14:15:43,010 [activeMQXAConnector.scheduler.1] jdbc.audit:
1. C


onnection.prepareStatement(INSERT into Testing1 (name, value) VALUES (?,?))
retu

rned net.sf.log4jdbc.PreparedStatementSpy@c92507
INFO 2007-09-07 14:15:43,010 [activeMQXAConnector.scheduler.1] jdbc.audit:
1. P
reparedStatement.setObject(1, abc 4444) returned
INFO 2007-09-07 14:15:43,010 [activeMQXAConnector.scheduler.1] jdbc.audit:
1. P
reparedStatement.setObject(2, 2007-09-07 14:15:43.01) returned
INFO 2007-09-07 14:15:43,010 [activeMQXAConnector.scheduler.1]
jdbc.sqlonly: IN
SERT into Testing1 (name, value) VALUES ('abc 4444',2007-09-07 14:15:43.01)
INFO 2007-09-07 14:15:43,010 [activeMQXAConnector.scheduler.1]
jdbc.sqltiming:
INSERT into Testing1 (name, value) VALUES ('abc 4444',2007-09-07
14:15:43.01) {
executed in 0 msec}
INFO 2007-09-07 14:15:43,010 [activeMQXAConnector.scheduler.1] jdbc.audit:
1. P
reparedStatement.executeUpdate() returned 1
INFO 2007-09-07 14:15:43,010 [activeMQXAConnector.scheduler.1] jdbc.audit:
1. P
reparedStatement.close() returned
************ resultMessage (1) :
org.mule.providers.DefaultMessageAdapter{id=ID:
DEVPC225-4323-1189145735916-1:0:1:1:1, payload=java.lang.String,
correlationId=c
335486f-5d09-11dc-9ef3-8368a873c9b2, correlationGroup=-1, correlationSeq=-1,
enc
oding=UTF-8, exceptionPayload=null, properties={
MULE_ENDPOINT=jdbc://insertRecord2
promptMessage=Please enter text...:
JMSExpiration=0
JMSTimestamp=1189145742604
JMSDestination=queue://esl/transactionQueue
JMSRedelivered=false
JMSCorrelationID=c335486f-5d09-11dc-9ef3-8368a873c9b2
JMSDeliveryMode=2
MULE_SESSION=SUQ9YzMzN2I5NzAtNWQwOS0xMWRjLTllZjMtODM2OGE4NzNjOWIyO0lEPWMzMzdiOTc
wLTVkMDktMTFkYy05ZWYzLTgzNjhhODczYzliMg==
MULE_ORIGINATING_ENDPOINT=endpoint.jms.esl.transactionQueue
JMSMessageID=ID:DEVPC225-4323-1189145735916-1:0:1:1:1
JMSPriority=4
MULE_CORRELATION_ID=c335486f-5d09-11dc-9ef3-8368a873c9b2
}}
********* resultMessage (2) :
org.mule.providers.DefaultMessageAdapter{id=ID:DEV
PC225-4323-1189145735916-1:0:1:1:1, payload=java.lang.String,
correlationId=c335
486f-5d09-11dc-9ef3-8368a873c9b2, correlationGroup=-1, correlationSeq=-1,
encodi
ng=UTF-8, exceptionPayload=null, properties={
MULE_ENDPOINT=jdbc://insertRecord2
promptMessage=Please enter text...:
JMSExpiration=0
JMSTimestamp=1189145742604
JMSDestination=queue://esl/transactionQueue
JMSRedelivered=false
JMSCorrelationID=c335486f-5d09-11dc-9ef3-8368a873c9b2
JMSDeliveryMode=2
MULE_SESSION=SUQ9YzMzN2I5NzAtNWQwOS0xMWRjLTllZjMtODM2OGE4NzNjOWIyO0lEPWMzMzdiOTc
wLTVkMDktMTFkYy05ZWYzLTgzNjhhODczYzliMg==
MULE_ORIGINATING_ENDPOINT=endpoint.jms.esl.transactionQueue
JMSMessageID=ID:DEVPC225-4323-1189145735916-1:0:1:1:1
JMSPriority=4
MULE_CORRELATION_ID=c335486f-5d09-11dc-9ef3-8368a873c9b2
}}
Hacked TransactionCoordination::getTransaction() returning
org.mule.transaction.
XaTransaction@92b1a1
Hacked AbstractTransaction::commit() starts at
org.mule.transaction.XaTransactio
n
Hacked XaTransaction::doCommit() is committing
bb14:38:0:01ec98354a41cd7cb6...e3
2001:
Hacked XaTransaction::doCommit() has committed
bb14:38:0:01ec98354a41cd7cb6...e3
2001:
Hacked TransactionCoordination::unbindTransaction() unbinding
org.mule.transacti
on.XaTransaction@92b1a1
Hacked TransactionCoordination::unbindTransaction() has unbound
org.mule.transac
tion.XaTransaction@92b1a1
Hacked AbstractTransaction::commit() ends
Hacked TransactionCoordination::getTransaction() returning null
Hacked AbstractTransaction::begin() starts at
org.mule.transaction.XaTransaction

Hacked XaTransaction::doBegin() has just started
bb14:38:0:01ec98354a41cd7cb6...
3bc002:
Hacked XaTransaction::doBegin() finds the transaction is of class
org.objectweb.
jotm.TransactionImpl
Hacked TransactionCoordination::bindTransaction() binding
org.mule.transaction.X
aTransaction@e5355f
Hacked TransactionCoordination::bindTransaction() has bound
org.mule.transaction
.XaTransaction@e5355f
Hacked AbstractTransaction::begin() ends
Hacked TransactionCoordination::getTransaction() returning
org.mule.transaction.
XaTransaction@e5355f

Please enter text...:
Hacked XaTransaction::setRollbackOnly() is being invoked with
bb14:38:0:01ec9835
4a41cd7cb6...3bc002:
Hacked XaTransaction::setRollbackOnly() has completed invocation with
bb14:38:0:
01ec98354a41cd7cb6...3bc002:
Hacked AbstractTransaction::rollback() starts at
org.mule.transaction.XaTransact
ion
Hacked XaTransaction::setRollbackOnly() is being invoked with
bb14:38:0:01ec9835
4a41cd7cb6...3bc002:
Hacked XaTransaction::setRollbackOnly() has completed invocation with
bb14:38:0:
01ec98354a41cd7cb6...3bc002:
Hacked XaTransaction::doRollback() is rolling back
bb14:38:0:01ec98354a41cd7cb6.
..3bc002:
Hacked XaTransaction::doRollback() has rolled back
bb14:38:0:01ec98354a41cd7cb6.
..3bc002:
Hacked TransactionCoordination::unbindTransaction() unbinding
org.mule.transacti
on.XaTransaction@e5355f
Hacked TransactionCoordination::unbindTransaction() has unbound
org.mule.transac
tion.XaTransaction@e5355f
Hacked AbstractTransaction::rollback() ends
Hacked TransactionCoordination::getTransaction() returning null
Hacked AbstractTransaction::begin() starts at
org.mule.transaction.XaTransaction

Hacked XaTransaction::doBegin() has just started
bb14:38:0:01ec98354a41cd7cb6...
10c003:
Hacked XaTransaction::doBegin() finds the transaction is of class
org.objectweb.
jotm.TransactionImpl
Hacked TransactionCoordination::bindTransaction() binding
org.mule.transaction.X
aTransaction@f894ce
Hacked TransactionCoordination::bindTransaction() has bound
org.mule.transaction
.XaTransaction@f894ce
Hacked AbstractTransaction::begin() ends
Hacked TransactionCoordination::getTransaction() returning
org.mule.transaction.
XaTransaction@f894ce
Hacked XaTransaction::setRollbackOnly() is being invoked with
bb14:38:0:01ec9835
4a41cd7cb6...10c003:
Hacked XaTransaction::setRollbackOnly() has completed invocation with
bb14:38:0:
01ec98354a41cd7cb6...10c003:
Hacked AbstractTransaction::rollback() starts at
org.mule.transaction.XaTransact
ion
Hacked XaTransaction::setRollbackOnly() is being invoked with
bb14:38:0:01ec9835
4a41cd7cb6...10c003:
Hacked XaTransaction::setRollbackOnly() has completed invocation with
bb14:38:0:
01ec98354a41cd7cb6...10c003:
Hacked XaTransaction::doRollback() is rolling back
bb14:38:0:01ec98354a41cd7cb6.
..10c003:
Hacked XaTransaction::doRollback() has rolled back
bb14:38:0:01ec98354a41cd7cb6.
..10c003:
Hacked TransactionCoordination::unbindTransaction() unbinding
org.mule.transacti
on.XaTransaction@f894ce
Hacked TransactionCoordination::unbindTransaction() has unbound
org.mule.transac
tion.XaTransaction@f894ce
Hacked AbstractTransaction::rollback() ends
Hacked TransactionCoordination::getTransaction() returning null
Hacked AbstractTransaction::begin() starts at
org.mule.transaction.XaTransaction

Hacked XaTransaction::doBegin() has just started
bb14:38:0:01ec98354a41cd7cb6...
e58004:
Hacked XaTransaction::doBegin() finds the transaction is of class
org.objectweb.
jotm.TransactionImpl
Hacked TransactionCoordination::bindTransaction() binding
org.mule.transaction.X
aTransaction@1e6e305
Hacked TransactionCoordination::bindTransaction() has bound
org.mule.transaction
.XaTransaction@1e6e305
Hacked AbstractTransaction::begin() ends
Hacked TransactionCoordination::getTransaction() returning
org.mule.transaction.
XaTransaction@1e6e305
CTRL-C trapped. Shutting down.
--
View this message in context: http://www.nabble.com/How-to-rollback-a-transaction--tf4391166.html#a12536621

hwt

unread,
Sep 7, 2007, 4:54:00 AM9/7/07
to us...@mule.codehaus.org

I inserted some println statements in JOTM classes, and noticed that when the
XA transaction was being committed, there was only one XA resource, which is
an ActiveMQ transaction context. I suppose that XA resource represents only
the JMS endpoint. The two JDBC endpoints seem to have been left out by
JOTM. Can this be due to Mule erroneously leaving them out?

Hacked TransactionCoordination::getTransaction() returning
org.mule.transaction.

XaTransaction@4cd580


Hacked AbstractTransaction::commit() starts at
org.mule.transaction.XaTransactio
n
Hacked XaTransaction::doCommit() is committing

bb14:38:0:01e56b01cbc94bb236...e3
9c01:
Hacked TransactionImpl::commit() finds term is null
Hacked SubCoordinator::commit_one_phase() starts
Hacked SubCoordinator::commit_one_phase() sees a default status
Hacked SubCoordinator::commit_one_phase() has a resource list size of 1
SubCoordinator::doOnePhaseCommit() starts
SubCoordinator::doOnePhaseCommit() finds resource is
org.apache.activemq.Transac
tionContext@1fa681c
SubCoordinator::doOnePhaseCommit() finds javax XID is
bb14:38:40:01e56b01cbc94bb
236...e39c01:01e56b01cbc94bb23640f...000000
SubCoordinator::doOnePhaseCommit() finds JOTM xid is
bb14:38:40:01e56b01cbc94bb2
36...e39c01:01e56b01cbc94bb23640f...000000
SubCoordinator::doOnePhaseCommit() asking resource to commit
SubCoordinator::doOnePhaseCommit() has got resource committed
SubCoordinator::doOnePhaseCommit() ends
Hacked TransactionImpl::commit() got the subcoord to commit one phase


Hacked XaTransaction::doCommit() has committed

bb14:38:0:01e56b01cbc94bb236...e3
9c01:


Hacked TransactionCoordination::unbindTransaction() unbinding
org.mule.transacti

on.XaTransaction@4cd580


Hacked TransactionCoordination::unbindTransaction() has unbound
org.mule.transac

tion.XaTransaction@4cd580


Hacked AbstractTransaction::commit() ends
Hacked TransactionCoordination::getTransaction() returning null
Hacked AbstractTransaction::begin() starts at
org.mule.transaction.XaTransaction

Hacked XaTransaction::doBegin() has just started

bb14:38:0:01e56b01cbc94bb236...
6b1c02:


Hacked XaTransaction::doBegin() finds the transaction is of class
org.objectweb.
jotm.TransactionImpl
Hacked TransactionCoordination::bindTransaction() binding
org.mule.transaction.X

aTransaction@c92507


Hacked TransactionCoordination::bindTransaction() has bound
org.mule.transaction

.XaTransaction@c92507


Hacked AbstractTransaction::begin() ends
Hacked TransactionCoordination::getTransaction() returning
org.mule.transaction.

XaTransaction@c92507

--
View this message in context: http://www.nabble.com/How-to-rollback-a-transaction--tf4391166.html#a12543291

Andrew Perepelytsya

unread,
Sep 7, 2007, 9:37:07 AM9/7/07
to us...@mule.codehaus.org
I recommend you try the latest trunk and replace your transaction manager with JBossTS (former ArjunaTS). It is now bundled in Mule, while JOTM had some flaws in XA implementation.

Andrew
Reply all
Reply to author
Forward
0 new messages