Re: Transaction State

[Rob Bugh <ro...@earthlink.net>]

I've created a test case that shows failover does not work for transacted
sessions on a JDBC Master/Slave topology. By this I mean when the slave
becomes the new master on failover, previously running transactions are not
respected by the new master. This leads to the situation where a message can
be retrieved twice (by two different consumers). See log messages below.

I created two consumers that try to retrieve messages from the same queue. I
use a JMX Group ID as well to force both messages to go to the same
consumer. To simulate processing time, when the first message is retrieved
by a consumer the consumer sleeps 60 seconds then commits the transaction to
remove the message from queue.

In this 60 second window I stop and restart the master broker. What I hoped
to happen was the consumers just seamlessly continue to work, i.e., the
consumer that retrieved the message finishes processing the message, commits
the transaction, retrieves the next message and continues on, etc..

What actually happens is when the failover occurs the second consumer grabs
the same message that the first consumer grabbed previously. When the first
consumer tries to commit the transaction an exception is thrown indicating
its transaction was not started.

Is this expected behavior? Is there a way to prevent duplication of the
messages? Remember this is a JDBC Master/Slave topology not a Pure
Master/Slave.

// The following is a log of the test described above.
//
// Test Run started. Consumer-2 grabbed the first message, sleeping for 60
seconds before committing.
[consumer-2] Fri May 02 14:29:36 CDT 2008: Retrieved Message, Group=g1,
message [ID=ID:rbugh-1191-1209756574943-0:2:1:1:1],
value=prop_value_1:1209756576646

// Broker failed over at this point. Note this is before consumer-2 issues
commit of the transaction.

- Transport failed, attempting to automatically reconnect due to:
java.net.SocketException: Connection reset
java.net.SocketException: Connection reset
	at java.net.SocketInputStream.read(SocketInputStream.java:168)
	at
org.apache.activemq.transport.tcp.TcpBufferedInputStream.fill(TcpBufferedInputStream.java:49)
	at
org.apache.activemq.transport.tcp.TcpBufferedInputStream.read(TcpBufferedInputStream.java:56)
	at java.io.DataInputStream.readInt(DataInputStream.java:353)
	at
org.apache.activemq.openwire.OpenWireFormat.unmarshal(OpenWireFormat.java:267)
	at
org.apache.activemq.transport.tcp.TcpTransport.readCommand(TcpTransport.java:156)
	at
org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:136)
	at java.lang.Thread.run(Thread.java:595)
- Transport failed, attempting to automatically reconnect due to:
java.net.SocketException: Connection reset
java.net.SocketException: Connection reset
	at java.net.SocketInputStream.read(SocketInputStream.java:168)
	at
org.apache.activemq.transport.tcp.TcpBufferedInputStream.fill(TcpBufferedInputStream.java:49)
	at
org.apache.activemq.transport.tcp.TcpBufferedInputStream.read(TcpBufferedInputStream.java:56)
	at java.io.DataInputStream.readInt(DataInputStream.java:353)
	at
org.apache.activemq.openwire.OpenWireFormat.unmarshal(OpenWireFormat.java:267)
	at
org.apache.activemq.transport.tcp.TcpTransport.readCommand(TcpTransport.java:156)
	at
org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:136)
	at java.lang.Thread.run(Thread.java:595)

// The new broker is now running...Notice that consumer-1 immediately picks
up the same message that
// consumer-2 did above. Compare message IDs.

[consumer-1] Fri May 02 14:29:49 CDT 2008: Retrieved Message, Group=g1,
message [ID=ID:rbugh-1191-1209756574943-0:2:1:1:1],
value=prop_value_1:1209756576646

// Consumer-2 transport layer detects a problem with the transaction. The
transaction doesn't exist
// on the new broker.

onException caught JMSException for [consumer-2]: javax.jms.JMSException:
Transaction 'TX:ID:rbugh-1191-1209756574943-0:1:1' has not been started.

// Consumer-2 attempts to commit the transaction and takes an exception.

[consumer-2] Fri May 02 14:30:36 CDT 2008: Committing transaction...

onException caught JMSException for [consumer-2]: javax.jms.JMSException:
Transaction 'TX:ID:rbugh-1191-1209756574943-0:1:1' has not been started.
Exception caught: javax.jms.JMSException: Transaction
'TX:ID:rbugh-1191-1209756574943-0:1:1' has not been started.

// Consumer-1 attemps to commit its transaction and it works.

[consumer-1] Fri May 02 14:30:49 CDT 2008: Committing transaction...

// Consumer-1 now moves on the the next message...

[consumer-1] Fri May 02 14:30:49 CDT 2008: Retrieved Message, Group=g1,
message [ID=ID:rbugh-1191-1209756574943-0:2:1:1:2],
value=prop_value_2:1209756576693
[consumer-1] Fri May 02 14:31:49 CDT 2008: Committing transaction...
-- 
View this message in context: http://www.nabble.com/Transaction-State-tp16968998s2354p17026701.html
Sent from the ActiveMQ - User mailing list archive at Nabble.com.

Re: Transaction State

[Rob Bugh <ro...@earthlink.net>]

Forgot to mention the test was run on ActiveMQ v4.1.1
-- 
View this message in context: http://www.nabble.com/Transaction-State-tp16968998s2354p17028108.html
Sent from the ActiveMQ - User mailing list archive at Nabble.com.