OrderingGroup and Transaction Rollback

[mclu]

Hi!

I just tested the new function ordering group of 1.4.4.GA because I want to replace my own ordering keeper implementation.
But What I see is that is does not work with transaction rolled back:

What I have done:

I add 4 Messages:

Connection connection = getConnection();
Session session = connection.createSession(false, Session.AUTO_ACKNOWLEDGE);
JBossMessageProducer sender = (JBossMessageProducer) session.createProducer(queue);
sender.enableOrderingGroup("testordergrp");

 TextMessage msg1 = session.createTextMessage("1");
 TextMessage msg2 = session.createTextMessage("Ordergrp - shouldrollback");
 TextMessage msg3 = session.createTextMessage("2");
 TextMessage msg4 = session.createTextMessage("3");
 sender.send(msg1);
 sender.send(msg2);
 sender.send(msg3);
 sender.send(msg4);
closeConnection(connection);

Those messages are added to the testqueue and as I also see they are added to the LinkedList in the OrderingGroup.class. So this seems to be fine.

On my server I have a service which starts a consumeSingle() method from an Statefull Session bean ( This method bean call automatically creates the XA Transaction). Inside this consumeSingle() method I now receive one message! and delegate it.

 conn = getConnection();
 boolean transacted = true;
 session = conn.createSession(transacted, Session.SESSION_TRANSACTED);

consumer = session.createConsumer(m_queue);

 // keep waittime small to ensure handling inside the transaction
 Message msg = consumer.receive(20000);

 // now delegate this message to the right handler....

The second message causes an error so the tx is rolled back.
In the old implementation the Message was also rolled back to the queue and the JMSXDeliveryCount was increased by one.
Next time consumeSingle() method was called this previous message was received again and again until it was moved to DLQ.

But with the new version and the orderinggroup on this behaviour changed?!?.
The second Message is still delivered as the second message but after the rollback first the other messages are delivered and at the end the second one again??

My server log:

INFO [TestMessageHandlerBean] Got:1 mID:ID:JBM-7228da24-988e-44e9-b1d5-36af6e220d3e
INFO [TestMessageHandlerBean] Got:Ordergrp - shouldrollback mID:ID:JBM-03e2198d-2e5d-490b-8631-56d596c689fe
ERROR [TestMessageHandlerBean] Error: Rollback because:For input string: "Ordergrp - shouldrollback"
INFO [TestMessageHandlerBean] Got:2 mID:ID:JBM-89bc4425-68f6-476e-abbf-b55938d36dca
INFO [TestMessageHandlerBean] Got:3 mID:ID:JBM-973afa1d-824a-4557-a316-9e9c1d6c9ed2
INFO [TestMessageHandlerBean] Got:Ordergrp - shouldrollback mID:ID:JBM-03e2198d-2e5d-490b-8631-56d596c689fe
ERROR [TestMessageHandlerBean] Error: Rollback because:For input string: "Ordergrp - shouldrollback"
INFO [TestMessageHandlerBean] Got:Ordergrp - shouldrollback mID:ID:JBM-03e2198d-2e5d-490b-8631-56d596c689fe
ERROR [TestMessageHandlerBean] Error: Rollback because:For input string: "Ordergrp - shouldrollback"
INFO [TestMessageHandlerBean] Got:Ordergrp - shouldrollback mID:ID:JBM-03e2198d-2e5d-490b-8631-56d596c689fe
ERROR [TestMessageHandlerBean] Error: Rollback because:For input string: "Ordergrp - shouldrollback"
INFO [TestMessageHandlerBean] Got:Ordergrp - shouldrollback mID:ID:JBM-03e2198d-2e5d-490b-8631-56d596c689fe
ERROR [TestMessageHandlerBean] Error: Rollback because:For input string: "Ordergrp - shouldrollback"
INFO [TestMessageHandlerBean] Got:Ordergrp - shouldrollback mID:ID:JBM-03e2198d-2e5d-490b-8631-56d596c689fe
ERROR [TestMessageHandlerBean] Error: Rollback because:For input string: "Ordergrp - shouldrollback"
INFO [TestMessageHandlerBean] Got:Ordergrp - shouldrollback mID:ID:JBM-03e2198d-2e5d-490b-8631-56d596c689fe
ERROR [TestMessageHandlerBean] Error: Rollback because:For input string: "Ordergrp - shouldrollback"
INFO [TestMessageHandlerBean] Got:Ordergrp - shouldrollback mID:ID:JBM-03e2198d-2e5d-490b-8631-56d596c689fe
ERROR [TestMessageHandlerBean] Error: Rollback because:For input string: "Ordergrp - shouldrollback"

Can you explain this? Does the orderingGroup does not work if a transaction is rolled back?

Just for the history info:
I don't think that my own solution has something to do with this. I simply receive() one message inside a transaction. This "service" just makes sure that only one message is handles by one consumer at a time. I first had a singleton MDB solution for this but the internal handling of message also queues at least 2 messages before delegating them to the MDB. So I had also problems with ordering and rollback there too...

[gaohoward]

Hi,

I'll take a look. Thanks

[gaohoward]

Hi,

If you roll back the transaction, the message will be redelivered.
the second message will not be delivered until the first message is consumed (committed in a Tx or just acknowledged).

Can you show me the code doing the rollback ? Thanks.

[mclu]

Hi!

Ok. Here is my method which receives the message from the queue.
There is also a slowdown feature but this can be ignored here.
The method is called at a statefull sessionbean with CMT so a transaction is just started.

 Session session = null;
 Connection conn = null;
 MessageConsumer consumer = null;
 try {
 conn = getConnection();
 boolean transacted = true;
 session = conn.createSession(transacted, Session.SESSION_TRANSACTED);

 consumer = session.createConsumer(m_queue);

 Logger.debug(this, "blocking to receive message from queue");

 // keep waittime small to ensure handling inside the transaction
 Message msg = consumer.receive(20000);
 if (msg != null) {
 // get deliverycount of the message. If it is the first time the count is 1
 int redeliveryCount = msg.getIntProperty("JMSXDeliveryCount");
 if (redeliveryCount > 1) {
 // at least the second retry so wait to slow consuming down
 // in ms: 10, 20, 40, 80, .... 102400 (at the 10 delivery)
 long waittime = (long) (10 * Math.pow(2, redeliveryCount));
 Logger.info(this, "Redelivery is slowed down. Waittime (ms):" + waittime);
 try {
 Thread.sleep(waittime);
 }
 catch (InterruptedException e) {
 // ignore
 }
 }
 // HERE the message is delegated to a handler. see expl. below
 jmsMessageHandler.handleMessage(msg);
 }
 }
 catch (JMSException e) {
 throw new RuntimeException("Problems handling message.", e);
 }
 finally {
 if (consumer != null)
 try {
 consumer.close();
 }
 catch (Exception ignore) {
 }
 if (session != null)
 try {
 session.close();
 }
 catch (Exception ignore) {
 }
 if (conn != null)
 try {
 conn.close();
 }
 catch (Exception ignore) {
 }
 }

So I open a connection, create a transacted session and receive ONE message. Then I delegate the message to a handler. In the final I close the resources.

The handler just uses:
private SessionContext ctx;
and then calls ctx.setRollbackOnly();

When I debug I see that the first message is delivered. The OrderingGroup.markSending() is called and the handler handles the message.
Then while the transaction is commited the unregister is called.

Now comes the failing message where the transaction is marked as rollback only. While the session is closed in the final block the unregister method is called again!! So the message is removedfrom the linked list!
Stack trace:

OrderingGroup.unregister(MessageReference) line: 121
OrderingGroupMonitor.unmarkSending(MessageReference) line: 178
MessagingQueue(ChannelSupport).cancelInternal(MessageReference) line: 609
MessagingQueue(PagingChannelSupport).cancelInternal(MessageReference) line: 323
MessagingQueue(ChannelSupport).cancel(Delivery) line: 328
SimpleDelivery.cancel() line: 110
ServerSessionEndpoint.cancelDeliveryInternal(Cancel) line: 1643
ServerSessionEndpoint.cancelDelivery(Cancel) line: 456
SessionAdvised.org$jboss$jms$server$endpoint$advised$SessionAdvised$cancelDelivery$aop(Cancel) line: 145
SessionAdvised$cancelDelivery_2980985335510575813.invokeNext() line: not available
ServerLogInterceptor.invoke(Invocation) line: 105
SessionAdvised$cancelDelivery_2980985335510575813.invokeNext() line: not available
SessionAdvised.cancelDelivery(Cancel) line: not available
SessionCancelDeliveryRequest.serverInvoke() line: 84
JMSServerInvocationHandler.invoke(InvocationRequest) line: 143
SSLBisocketServerInvoker(ServerInvoker).invoke(InvocationRequest) line: 862
ServerThread.processInvocation(SocketWrapper) line: 609
ServerThread.dorun() line: 421
ServerThread.run() line: 174

What I see in OrderingGroupMonitor is that unmarksending AND messageCompleted has more or less the same code? Can this be right?
Both call:
OrderingGroup group = orderingGroups.get(grpName);
if (group != null)
{
group.unregister(ref);
}


Greets

[gaohoward]

Re:
What I see in OrderingGroupMonitor is that unmarksending AND messageCompleted has more or less the same code? Can this be right?

Yes, they are pretty much the same. The reason why there are two methods is that originally we keep the topic in mind, so there is a reference count for each message. unmarksending is used to be a method just decrease the ref count, the messageCompleted() is used to unlink the message. But later we decided not to support the topic for now. So the reference count doesn't make much sense now. It should be simplified.

Howard

[mclu]

Thx for explanation.

But still, why is my message after the rollback not the next message, which is delivered by the JMS System.

I still have this reproduceable:

1, Rollbackmsg(first try) , 2, 3 , Rollbackmsg(second try), ... , Rollbackmsg(last try)
( simplified: A, B, C, D, B, B, B, B, B)

behaviour
instead of the expected:

1, Rollbackmsg(first try), Rollbackmsg(second try), ... , Rollbackmsg(last try), 2, 3
( simplified: A, B, B, B, B, B, B, C, D )

I think is must have something to do with this session.close() call which removes the reference from the Orderinggroup....

Can you explain? Bug or Feature :-)?

[gaohoward]

Hi,

It is a obvious bug. The problem is that the unmarkSend() method shouldn't call the unregister() to release the ref in the cancel operation.

As for the receiving sequence, I need to find out the reason.
I'll create a JIRA.

Thanks!

Howard

[gaohoward]

https://jira.jboss.org/jira/browse/JBMESSAGING-1643

The reason for the wrong order of delivery:

1. msg A is delivered and commited. then B is delivered to client.
2. consumer close() cause B cancelled back to queue. But it is wrongly removed from the linked list.
3. On next deliver, B cannot be delivered because it is not the first in the ordering group (B still an ordering group message). So C is delivered to client.
4. After C is committed, D is delivered to the client and committed.
5. then B is delivered as the whole ordering group is empty now.