Bug 733383 - Single message can be delivered to multiple client
Summary: Single message can be delivered to multiple client
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise MRG
Classification: Red Hat
Component: qpid-java
Version: 2.0
Hardware: All
OS: All
high
high
Target Milestone: 2.1.2
: ---
Assignee: Weston M. Price
QA Contact: MRG Quality Engineering
URL:
Whiteboard:
: 748863 (view as bug list)
Depends On: 752946
Blocks: 783492
TreeView+ depends on / blocked
 
Reported: 2011-08-25 15:26 UTC by Martin Vecera
Modified: 2016-02-22 00:59 UTC (History)
12 users (show)

Fixed In Version: qpid-java-0.14-1.el5
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2012-04-30 17:52:17 UTC


Attachments (Terms of Use)
Updated examples to aid in testing (53.78 KB, application/java-archive)
2011-09-05 08:52 UTC, Weston M. Price
no flags Details
Console output for BZ-733383 MRGJCAMessageBean run (183.69 KB, text/plain)
2011-09-05 18:43 UTC, Weston M. Price
no flags Details
Java code to parse logs looking for inadvertent redelivery of messages (3.66 KB, application/java-archive)
2011-09-05 18:55 UTC, Weston M. Price
no flags Details
Broker log for 733383 (1.58 MB, application/octet-stream)
2011-09-06 11:52 UTC, Weston M. Price
no flags Details
Broker log for test run (1.11 MB, application/octet-stream)
2011-09-06 17:57 UTC, Weston M. Price
no flags Details


Links
System ID Priority Status Summary Last Updated
Red Hat Product Errata RHSA-2012:0529 normal SHIPPED_LIVE Moderate: Red Hat Enterprise MRG Messaging 2.1 security and enhancement update 2012-04-30 21:48:25 UTC

Description Martin Vecera 2011-08-25 15:26:50 UTC
Description of problem:
According to JMS standard, when there are multiple clients connected to a queue. Each message can be delivered only to one client. When I have Message Driven Bean with 15 instances (default value) in EAP 5.1.1 and MRG queue connected with JCA adapter, message is usually delivered to two instances simultaneously. In some cases, it is delivered once or even three times.

How reproducible: 100%


Steps to Reproduce:
1. checkout https://svn.devel.redhat.com/repos/jboss-qa/mrg/tests/mdb
2. fix annotation in /mdb-ejb/src/main/java/org/jboss/test/mdb/MRGJCAMessageBean.java to point to your MRG server
3. compile with mvn -DskipTests clean package
4. copy mdb/mdb-test/target/mdb-test.ear to deploy directory of EAP 5.1.1 (profile production)
5. checkout https://svn.devel.redhat.com/repos/jboss-qa/mrg/qpid-java-jca
6. configure qpid-java-jca/qpid-jca-ds.xml to point to your MRG server
7. Start EAP
8. Go to http://www.imdb.com/title/tt0112870/ and wait for the test to finish.
  
Actual results:
In server log, you can see simulated exceptions that should cause every 5th message to be redelivered (redelivery work). However, every message should be delivered exactly once. In your browser you can see each message confirmed and a log of messages that has been delivered multiple times. First number in acknowledged message is MDB's hashCode(). So you can see that the same message that was delivered for the first time (i.e. no redelivery) is processed by two instances at the same time:
1929003823 test01 Messaggio numero 1 ACK
501179115 test01 Messaggio numero 1 ACK

This must not happen.

Comment 1 Weston M. Price 2011-09-01 15:27:44 UTC
Please provide the *-ds.xml file you are using.

Comment 2 Martin Vecera 2011-09-02 07:49:38 UTC
The *-ds.xml file is in SVN, step 6. mentions its configuration. What is in SVN is the exact form I use.

Btw. the URL in step 8 is wrong - you should not go to IMDB to see the famous Indian movie. Instead start the test with:
http://localhost:8080/mdb-servlet/mrgtest?op=test01

Comment 3 Weston M. Price 2011-09-02 08:53:32 UTC
Note, I notice in a lot of your example code your not using a try/finally block in your onMessage() methods. Please modify your code to use these as if there is an exception, your sessions will not be correctly closed and returned to the connection pool.

Comment 4 Weston M. Price 2011-09-02 09:05:27 UTC
Ok, based on the instructions above, I notice in your MDB, you are using 

@ActivationConfigProperty(propertyName = "destination", propertyValue = "queue/mrg_mrg_jca_mdb_transactions_in"),

as your destination, but I don't see this in your corresponding *-ds.xml file from the project in step 5

https://svn.devel.redhat.com/repos/jboss-qa/mrg/qpid-java-jca/qpid-jca-ds.xml

Am I missing something? 

I need to see the syntax you are using to configure the queue/mrg_mrg_jca_mdb_transactions_in.

Comment 5 Weston M. Price 2011-09-02 10:07:50 UTC
Note, if you are using for your destinationAddress, then you will see this type of behavior as amq.direct is an exchange NOT a queue. Please refer to 

https://bugzilla.redhat.com/show_bug.cgi?id=735030

for more explanation on the amq.direct syntax and what this means.

Comment 6 Weston M. Price 2011-09-02 10:08:32 UTC
Sorry, above should read:

Note, if you are using amq.direct for your destinationAddress, then you will see this type
of behavior as amq.direct is an exchange NOT a queue. Please refer to 

https://bugzilla.redhat.com/show_bug.cgi?id=735030

for more explanation on the amq.direct syntax and what this means.

Comment 7 Martin Vecera 2011-09-02 13:19:48 UTC
The queue definitions are in SVN as well, in the EAR module: https://svn.devel.redhat.com/repos/jboss-qa/mrg/tests/mdb/mdb-test/src/main/application/queues-service.xml

Yes, I use amq.direct as I was told to. Is there any complete user guide that has the information what is allowed/recommende? We lose a lot of time by these blind shots :-(

I agree with your note on finally blocks. However, I never got an exception in a place that would keep the session opened. So I assume that this won't affect the test results.

Comment 8 Martin Vecera 2011-09-02 13:26:49 UTC
I obviously have the queues configured in a way that you recommended in https://bugzilla.redhat.com/show_bug.cgi?id=735030

Comment 9 Weston M. Price 2011-09-02 13:28:27 UTC
Yes, I use amq.direct as I was told to. Is there any complete user guide that
has the information what is allowed/recommende? We lose a lot of time by these
blind shots :-(

There is an existing BZ

https://bugzilla.redhat.com/show_bug.cgi?id=729131

which is a request for formal documentation. However the two relevant README files are attached to this BZ which has the latest documentation updates. I am sorry you were not apprised of this, you should have been. It was discussed in our weekly JCA meeting which I am not sure if you attend or not. 

At any rate, sorry for the confusion.

Comment 10 Martin Vecera 2011-09-02 13:51:38 UTC
So it seems that my approach in queues configuration is the recommended one...

Comment 11 Weston M. Price 2011-09-03 18:36:19 UTC
Example:


<mbean code="org.jboss.resource.deployment.AdminObject"
         name="qpid.jca:name=HelloQueue">
     <attribute name="JNDIName">HelloQueue</attribute>
     <depends optional-attribute-name="RARName">jboss.jca:service=RARDeployment,name='qpid-ra-0.10.rar'</depends>
     <attribute name="Type">javax.jms.Destination</attribute>
     <attribute name="Properties">
        destinationType=QUEUE
        <!--note if you require the older BURL syntax, uncomment the line below and comment the ADDR syntax line>
        destinationAddress=BURL:direct://amq.direct//hello.Queue
        destinationAddress=hello.Queue;{create:always, node:{type:queue, x-declare:{auto-delete:true}}}
        -->
        destinationAddress=direct://amq.direct//hello.Queue?autodelete='true'
     </attribute>
  </mbean>


Note, the BURL syntax in use


@MessageDriven(activationConfig = {
		   @ActivationConfigProperty(propertyName = "acknowledgeMode", propertyValue = "Auto-acknowledge"),
		   @ActivationConfigProperty(propertyName = "destinationType", propertyValue = "javax.jms.Queue"),
		   @ActivationConfigProperty(propertyName = "destination", propertyValue = "HelloQueue"),
		   @ActivationConfigProperty(propertyName = "connectionURL", propertyValue = "amqp://anonymous:@client/test?brokerlist='tcp://10.0.1.44:5672?sasl_mechs='ANONYMOUS''"),
           @ActivationConfigProperty(propertyName = "maxSession", propertyValue = "10")
		   
})
public class QpidHelloListenerBean implements MessageListener 

---


 <mbean code="org.jboss.resource.deployment.AdminObject"
         name="qpid.jca:name=GoodByeQueue">
     <attribute name="JNDIName">GoodByeQueue</attribute>
     <depends optional-attribute-name="RARName">jboss.jca:service=RARDeployment,name='qpid-ra-0.10.rar'</depends>
     <attribute name="Type">javax.jms.Destination</attribute>
     <attribute name="Properties">
        destinationType=QUEUE
        <!--note if you require the older BURL syntax, uncomment the line below and comment the ADDR syntax line>
        destinationAddress=goodbye.Queue;{create:always, node:{type:queue, x-declare:{auto-delete:true}}}
        -->
        destinationAddress=direct://amq.direct//goodbye.Queue
     </attribute>
  </mbean>

@MessageDriven(activationConfig = {
        @ActivationConfigProperty(propertyName = "acknowledgeMode", propertyValue = "Auto-acknowledge"),
        @ActivationConfigProperty(propertyName = "destinationType", propertyValue = "javax.jms.Queue"),
        @ActivationConfigProperty(propertyName = "destination", propertyValue = "GoodByeQueue"),
        @ActivationConfigProperty(propertyName = "connectionURL", propertyValue = "amqp://anonymous:@client/test?brokerlist='tcp://10.0.1.44:5672?sasl_mechs='ANONYMOUS''"),
        @ActivationConfigProperty(propertyName = "useLocalTx", propertyValue = "false"),
        @ActivationConfigProperty(propertyName = "maxSession", propertyValue = "10")

})
public class QpidGoodByeListenerBean implements MessageListener


start EAP:

14:26:51,613 INFO  [AdminObject] Bound admin object 'org.apache.qpid.ra.admin.QpidDestinationProxy' at 'HelloQueue'
14:26:51,620 INFO  [AdminObject] Bound admin object 'org.apache.qpid.ra.admin.QpidDestinationProxy' at 'GoodByeQueue'

Send a message with client either web or RMI

ant -Dtarget.platform=jboss run-client

  [java] 582  [main] DEBUG org.apache.qpid.jca.example.client.QpidTestClient  - Found SLSB qpid-jcaex/QpidTestBean/remote
     [java] 582  [main] DEBUG org.apache.qpid.jca.example.client.QpidTestClient  - Sending 1 message(s) with content: Hello, Goodbye, World! with destination type Queue


Server:

14:35:03,837 INFO  [QpidHelloListenerBean] Received text message with contents Hello, Goodbye, World! at Sat Sep 03 14:35:03 EDT 2011

Note, the message is only received once being that this MDB is listening on the hello.Queue destination. Note, the GoodbyeBean did not receive this message either.

Comment 12 Weston M. Price 2011-09-04 00:04:55 UTC
Note, the syntax for the above queue should be:

destinationAddress=direct://amq.direct//hello.Queue?autodelete='true',routingkey='hello.Queue'

Comment 13 Weston M. Price 2011-09-05 08:50:47 UTC
I am attaching jca-examples.jar which is a rework of the JCA examples providing much more realistic examples for Queue/Topics, syntax etc. This should give better examples that what was previously provided. There is a BZ for this 735322, but I thought I would get the work out early so you can start taking a look. 

Alternatively you can check it out from GitHub as well:

git://github.com/astitcher/qpid-jca.git

branch is wp-BZ-735322

Comment 14 Weston M. Price 2011-09-05 08:52:21 UTC
Created attachment 521453 [details]
Updated examples to aid in testing

Updated examples to aid in testing

Comment 15 Martin Vecera 2011-09-05 12:25:33 UTC
Hello Weston,

please give it a try with my example. I had to make my test working. You have everything what you need to run it. 

I have doubts that sending a single message could reproduce the issue. Single message can only initialize a single instance of a MDB in the pool. That will be reused next time as well. So there won't be multiple deliveries.

I use routingkey in my queue deployment. Overall, I could not find any configuration difference between your examples and my test.

Comment 16 Weston M. Price 2011-09-05 12:37:08 UTC
Can you clarify EXACTLY what the issue is? I am having a hard time understanding what you think is a defect. 

In the case of of an exception in onMessage(), depending upon your transactional configuration (i.e. you are using XA) the message will be redelivered. However, the message does not have to be redelivered to the SAME instance for this to be correct. MDB instances are stateless and as such it does not matter which one process the redelivered message. 


Please clarify if I am missing something.

Comment 17 Martin Vecera 2011-09-05 13:00:38 UTC
Forget completely about simulated exception and redelivery. Even if you comment that out, a message can be processed bu multiple MDBs at the same time.

In the source code, you can see that the message is confirmed (send to out queue) after the simulated exception. So no message could be confirmed twice (or more times).

Is that more clear now?

Comment 18 Martin Vecera 2011-09-05 13:01:19 UTC
And please note that I have exactly the same code with JBoss Messaging that works fine.

Comment 19 Weston M. Price 2011-09-05 13:12:08 UTC
'Forget completely about simulated exception and redelivery. Even if you comment
that out, a message can be processed bu multiple MDBs at the same time.'

A single message cannot. 

Do me a favor, in your code modify it to print out the hashCode, or instance id of the MDB, AND the message. Run a test that send's 50 messages etc and show me in the trace where two MDB's are processing the SAME message something like:

09:11:14,956 INFO  [STDOUT] MDB id: 487836948 MessageID ID:a7693305-e29d-36f9-9393-06b99a52b297
09:11:14,956 INFO  [STDOUT] MDB id: 245742581 MessageID ID:c49b6376-9778-38d6-89a0-0882ebc46c0f
09:11:14,956 INFO  [STDOUT] MDB id: 584505686 MessageID ID:c1ed67fd-d24d-31a8-9d7f-768e76c94d9e
09:11:14,956 INFO  [STDOUT] MDB id: 1196863224 MessageID ID:9684f531-b464-396c-9629-6876efa96adc
09:11:14,956 INFO  [STDOUT] MDB id: 200884319 MessageID ID:50606ec0-78cb-378b-87d9-ee09dc790f00
09:11:14,957 INFO  [STDOUT] MDB id: 418456349 MessageID ID:8c1c1c9a-bf24-36a7-a029-843f85b70dd1
09:11:14,957 INFO  [STDOUT] MDB id: 2134397365 MessageID ID:835958a4-db43-35b2-a3c3-40aea40a7269
09:11:14,957 INFO  [STDOUT] MDB id: 1249674067 MessageID ID:4841e208-80d0-34c8-b898-180a57bc79aa
09:11:14,958 INFO  [STDOUT] MDB id: 881976409 MessageID ID:7b67233b-4472-34ac-b49a-83bb54242db1
09:11:14,958 INFO  [STDOUT] MDB id: 1445374469 MessageID ID:b42dd2ce-4798-3a2a-bfc2-689495fb94fe
09:11:15,186 INFO  [STDOUT] MDB id: 1445374469 MessageID ID:e37329db-f73e-3aff-82cf-742358fafb14
09:11:15,186 INFO  [STDOUT] MDB id: 418456349 MessageID ID:9eccc654-c2a4-31c8-a055-272e83ee2d89
09:11:15,188 INFO  [STDOUT] MDB id: 418456349 MessageID ID:2962c322-bb38-39ef-b2d2-7be8ab8945f1
09:11:15,188 INFO  [STDOUT] MDB id: 1249674067 MessageID ID:a657c234-dc91-368c-8a79-8e8df61fbbc8
09:11:15,188 INFO  [STDOUT] MDB id: 1445374469 MessageID ID:1898bd7c-b5ea-3690-92f0-7c320bb08630
09:11:15,188 INFO  [STDOUT] MDB id: 881976409 MessageID ID:d260dcef-e19b-33c6-ada4-261288e301d2
09:11:15,189 INFO  [STDOUT] MDB id: 1445374469 MessageID ID:7a015959-f630-3a5d-a68e-f213247242dc
09:11:15,190 INFO  [STDOUT] MDB id: 1249674067 MessageID ID:4c7412e6-7959-315d-9fa0-f1f244f928a2
09:11:15,190 INFO  [STDOUT] MDB id: 418456349 MessageID ID:8919e95a-b15e-3bb4-8845-6939e0a36d43
09:11:15,198 INFO  [STDOUT] MDB id: 418456349 MessageID ID:61173068-0d67-33c4-9578-77dd221da63e

Comment 20 Weston M. Price 2011-09-05 13:47:09 UTC
Also note what you should see in the case of redelivery

09:37:17,119 INFO  [STDOUT] MDB id: 1345973544 MessageID ID:3d4d3553-b410-32f7-b988-d6dc5bccd392 redel false
09:37:17,119 INFO  [STDOUT] MDB id: 1883297302 MessageID ID:9f6ac14d-fd61-357e-98c1-43be5ab918d3 redel false
09:37:17,119 INFO  [STDOUT] MDB id: 184616510 MessageID ID:5770f311-62a5-372b-b2e7-ae3bdcb152b6 redel false
09:37:17,119 INFO  [STDOUT] MDB id: 1118994831 MessageID ID:17b77bb3-4c09-3c5a-85e8-61c58c2af72e redel false
09:37:17,120 INFO  [STDOUT] MDB id: 816281581 MessageID ID:373fb7b7-1577-3558-b213-9e01c2ad0a42 redel false
09:37:17,123 ERROR [QpidHelloListenerBean] Testing redelivery! for instance org.apache.qpid.jca.example.ejb.QpidHelloListenerBean@30a777ed
09:37:17,181 INFO  [STDOUT] MDB id: 1883297302 MessageID ID:74726ad6-79d4-3349-a61c-aff919cb5aaa redel false
09:37:17,181 INFO  [STDOUT] MDB id: 816281581 MessageID ID:373fb7b7-1577-3558-b213-9e01c2ad0a42 redel true

Note the message id: 373fb7b7-1577-3558-b213-9e01c2ad0a42

This occurs twice as a result of redelivery being executed.

Comment 21 Martin Vecera 2011-09-05 15:03:53 UTC
I revealed strange thing. Sometimes a message gets redelivered even when there is no exception in MDB.

The code is:
if (!message.getJMSRedelivered() && (exceptionCounter++ % 5) == 0) { 
  throw new EJBException("Eccezione simulato!");
}
sendMessage(this.hashCode() + " " + text + " ACK");
System.out.println(this.hashCode() + " '" + text + ",' Redelivery: " + message.getJMSRedelivered());
System.out.println("Messaggio '" + text + " ACK' inviato alla coda di destinazione.");  

And the log is:
2011-09-05 16:48:06,723 INFO  [STDOUT] (Dispatcher-Channel-8) 1474192407 'test01 Messaggio numero 23,' Redelivery: false
2011-09-05 16:48:06,723 INFO  [STDOUT] (Dispatcher-Channel-8) Messaggio 'test01 Messaggio numero 23 ACK' inviato alla coda di destinazione.
...
2011-09-05 16:50:27,818 INFO  [STDOUT] (Dispatcher-Channel-13) 37225610 'test01 Messaggio numero 23,' Redelivery: true
2011-09-05 16:50:27,818 INFO  [STDOUT] (Dispatcher-Channel-13) Messaggio 'test01 Messaggio numero 23 ACK' inviato alla coda di destinazione.

The whole code of MDB onMessage() method is in try-catch block and there is no exception withing delivering message number 23.

There is no other exception in the server log except for the simulated ones. But not during delivering message number 23.

Comment 22 Weston M. Price 2011-09-05 15:06:57 UTC
Let's start with the initial issue. Did you run what I asked to print the hashCode and message id?

I want to eliminate the duplicate issue before I look at something else.

Comment 23 Weston M. Price 2011-09-05 15:12:46 UTC
BTW, for the delivery question, JMS does not guarantee WHEN re-delivery is going to occur. So, you could be seeing a message being redelivered that is the result of an exception occurring from before.  The message number 23 is irrelevant here:

Try putting this line in your MDB: 

System.out.println("MDB id: " + this.hashCode() + " " + message.getJMSMessageID() + " redel " + message.getJMSRedelivered());



This will tell you the id of the MDB instance, the message id, and whether or not it was redelivered. Again, what order redelivery arrives in is not guaranteed so whether it comes as message 23 or 50 does not matter. The MessageID does. 

Also, any logs messages, if you don't mind, translate them into English so I can read them.

Comment 24 Weston M. Price 2011-09-05 15:14:49 UTC
Again, let me be clear...

Any logs/console etc I want

The instanceid/hashcode of the MDB
The JMS Message ID as message.getJMSMessageID() 
The redelivery status message.getJMSRedelivered()

Your counter and state variables I don't care about.

Comment 25 Martin Vecera 2011-09-05 15:25:46 UTC
This is still the same issue. I have a feeling like you do not want to find the issue. Of course I know that message order is not guaranteed. Just run the my application in a way it is described in the issue. It will show you the problem reliably. I can provide you the deployment (.ear) if you wanted.

If you read my Comment 21 you could see, that the MDBs hash code is present in the output.

I do not need to print message ID. The number is part of the message content sent by client. Each message is recognized by its content. And each content must be delivered. I run the test in a way you wanted.

I send 1000 messages. Every 5th message should be redelivered. However, additional 12 messages gets redelivered as well without any obvious reason.

If I put the system under heavier load (sending more messages in a transaction and commiting it at once), the redelivery occurs almost in the same time with delivery and can even happen more than twice.

For you too see this, there is the sample application I created.

Comment 26 Weston M. Price 2011-09-05 16:09:49 UTC
'I have a feeling like you do not want to find the
issue.'

Nothing could be further from the truth. This is why I am looking at it. Sorry you feel this way. Your MDB is not doing anything special and can be easily replicated. However, I need better logs/console output. I am simply asking for more information. The message id is important as it allows me coordinate seeing WHICH messages are being redelivered and how many times. The message id is important in this situation. 

I have written a utility program that can parse the 

System.out.println("MDB id: " + this.hashCode() + " " + message.getJMSMessageID() + " redel " + message.getJMSRedelivered());

string from a file and record exactly how many times a message was redelivered. Since your code blocks throwing an exception for redelivered messages, every redelivered message should only be redelivered once being that if it's redelivery status is true, we don't rethrow the exception.

 I am simply using this as a way to understand the issue better. Again, I am not saying there isn't an issue I just need more to work with. 

I ran a test on my system with 1000 messages rolling back the transaction every 5th message (redelivery).  my utility program showed no messages re-delivered more than once. The reason I asked for the debug string is to make this process easier. 

Let's coordinate and see if we can come up with a solution. I am not running your test program directly because 

1) I don't use Maven because nothing we do on the MRG team depends on it.

2) I believe we should have different tests doing the same thing but not exactly the same as this wouldn't prove all that much since we know your test 'fails'. Having the same behavior in another test would either prove or disprove the test is wrong. That's all.

Again, if you can put that debug string in, comment out every other log statement, run your test and send me the output then I can analyze it and get a better idea of what is going on.

Comment 27 Gordon Sim 2011-09-05 16:23:42 UTC
Attaching trace level broker logs for as simple a scenario as possible while still demonstrating the problem would also be a useful way to get more information about the issue. You can turn them on by specifying --log-enable trace+:amqp_0_10 to qpidd (or adding log-enable=trace+ to qpidd.conf)

Comment 28 Weston M. Price 2011-09-05 18:41:34 UTC
Ok, first off, thanks for your patience.

I was able to checkout and build your code no problem. I installed Maven and compiled with no issues. However, in your code you had commented out:

/*if (!message.getJMSRedelivered() && (exceptionCounter++ % 5) == 0) {
                  throw new EJBException("Eccezione simulato!");
 }*/

I uncommented this and ran a test with 1000 messages for this listener. The only thing I changed was the addition of the debug string

System.out.println("MDB id: " + this.hashCode() + " " + message.getJMSMessageID() + " redel " + message.getJMSRedelivered());

as well as removing some extraneous debug statements.

As I mentioned before, the jmsMessageID() provides us with a way to know exactly how many times a message has been delivered as this ID, once set, never changes. The Broker does not modify this ID in anyway and it is generated by the JMS client after the send method completes: 

As per the JMS specification, section 3.4.3:

'The JMSMessageID header field contains a value that uniquely identifies each
message sent by a provider.
When a message is sent, JMSMessageID is ignored. When the send method returns, the field contains a provider-assigned value.
A JMSMessageID is a String value which should function as a unique key for identifying messages in a historical repository. The exact scope of uniqueness is provider defined. It should at least cover all messages for a specific installation of a provider where an installation is some connected set of message routers.'

Since a MessageID is never altered once set, it is the best way to determine how many times a particular message has been redelivered since you can get this information directly from the message and you do not have to rely on setting text content to determine re-delivery semantics.

After running the test, my analyzer program could not find a message that had been redelivered more than once over the entire test. I used a standalone client to execute the test being that 

https://bugzilla.redhat.com/show_bug.cgi?id=722614

prevents using an XA connection factory without an actual managed transaction being started. Note, if you wanted to modify your servlet to wrap the

else if (op.equals("test01")) 

 code in a UserTransaction, this would work as well.

The analyzer program I mention simply takes a file as input and evaluates all lines with the string:

14:10:49,393 INFO  [STDOUT] MDB id: 341305436 ID:2f69b029-e1d6-3b49-bb40-20bbe114e8c9 redel false

It stores the MessageID as a key in a hash map and increments the number of times it appears in the file. 

At the end of the analysis if a MessageID has been re-delivered more than one time (as the number would be greater than one), it prints out the MessageID and how many times it was re-delivered. Nothing in the analysis shows that this was the case and I have run it multiple times with your application.

I am attaching the log file as well as the code to be able to parse the file. At this point, I simply don't see anything to indicate messages are being redelivered in the case where an exception was not simulated/throw etc. 

As for the statement:

'I send 1000 messages. Every 5th message should be redelivered. However,
additional 12 messages gets redelivered as well without any obvious reason.'

If you could actually show me where this is happening, or at the very least, some form of reasonable log/output that this is the case I would be more than happy to take a further look. Again, the MessageID is the best way to determine this as it is system generated/managed.


Again, I am attaching one of the logs from my test run as well as well as the simple program to parse the log file.

Comment 29 Weston M. Price 2011-09-05 18:43:28 UTC
Created attachment 521532 [details]
Console output for BZ-733383 MRGJCAMessageBean run

Comment 30 Weston M. Price 2011-09-05 18:55:33 UTC
Created attachment 521537 [details]
Java code to parse logs looking for inadvertent redelivery of messages

to run

java -cp ~/mdbanalyzer.jar org.jboss.mrg.jca.analyzer.MDBOutputReader <file-name>

Comment 31 Weston M. Price 2011-09-05 20:06:00 UTC
Ok, let's look at the receiving side of your code (MRGTestServlet) to see what we can come up with:

First off, I am not sure how you are able to run this with an XAConnectionFactory unless you have disabled XATransactions on the send because of BZ-722614, but not matter, assuming we are able to send and receive via the Servlet. 

We get here: 


                  String text = ((TextMessage) msg).getText();
                  String parsedText = text.substring(0, text.length() - 4);
                  parsedText = parsedText.substring(parsedText.lastIndexOf(" ") + 1);

                  Integer msgId = Integer.valueOf(parsedText);

This actually throws a NumberFormatException because the parsedText ends up being test01 since the complete message text would be:

<hashcode> test01 ACK

Example:

1682926188 test01 ACK (note I am running this test from your code)

So, what I believe you meant was

parsedText = parsedText.substring(0, parsedText.indexOf(" "));

since you want the value of the hashCode for the MDB instance which you are using as a msgID of sorts because you are indexing into a HashTable based on the hashCode as a key.

Once all the messages are processed (note you may timeout on the receive) you do something like:

  boolean checkOccurrences = true;
               for (int i = 0; i < MESSAGE_COUNT; i++) {
                  Integer occurr = receivedMessages.get(i);
                  if (occurr == null || occurr != 1) {
                     out.println("Numero errato di occorrenze (" + occurr + ") di messaggio numero " + i + ".");
                     checkOccurrences = false;
                  }
               }

So, what we are doing is iterating 1000 times (MESSAGE_COUNT) but you are looking in the HashMap based on i which is 1 - 1000 so, what you are basically saying is that you are looking for a message with an id of 1, 2, 3, 4

I am not sure how this would ever work as the key into the receivedMessages map is the HashCode of the MDB instance, not the message delivery count. 

What you really want to do is use the jmsMessageID for receivedMesages and increment how many times it actually was delivered. Something like the following pseudo code:


public void doTest01
{
   //Produce MESSAGE_COUNT messages here
   //Close the producer and the session





}

Comment 32 Weston M. Price 2011-09-05 20:40:17 UTC
Sorry, hit return too soon (been a long day)

So, to continue;

Using the hashCode to determine redelivery is not going to work either. Take a look at the following logs:

6:33:25,404 INFO  [STDOUT] MDB id: 1758624048 ID:45638dc1-f5d0-326e-acd5-eec9dff1578e redel false
16:33:25,405 INFO  [STDOUT] MDB id: 878264074 ID:48f5e4e7-6eac-3c89-a14c-3eaa306c6d7a redel false
16:33:25,407 INFO  [STDOUT] MDB id: 1502306715 ID:2482ea1b-f12a-325e-945b-261bcde3fca5 redel false
16:33:25,407 INFO  [STDOUT] MDB id: 1329185887 ID:959366a1-af39-33eb-bc62-b36779a5f6f5 redel false
16:33:25,407 INFO  [STDOUT] MDB id: 1680832898 ID:f32a62bd-2665-3db7-8c75-c27b6d162d75 redel false
16:33:25,407 INFO  [STDOUT] MDB id: 866995041 ID:3e4e90c3-c4f6-39d0-a20c-649dc0c0bae2 redel false
16:33:25,423 ERROR [TxPolicy] javax.ejb.EJBException: Eccezione simulato!
16:33:25,424 ERROR [QpidMessageHandler] Failed to deliver message
javax.ejb.EJBException: Eccezione simulato!
	//Cut out stack trace
16:33:25,537 INFO  [STDOUT] Inizializzato.
16:33:25,537 INFO  [STDOUT] MDB id: 591288121 ID:f32a62bd-2665-3db7-8c75-c27b6d162d75 redel true


Take a look at the message with id

f32a62bd-2665-3db7-8c75-c27b6d162d75

Note, the first MDB instance that handled the message:


16:33:25,407 INFO  [STDOUT] MDB id: 1680832898 ID:f32a62bd-2665-3db7-8c75-c27b6d162d75 redel false

Now, take a look at the second:

16:33:25,537 INFO  [STDOUT] MDB id: 591288121 ID:f32a62bd-2665-3db7-8c75-c27b6d162d75 redel true

They are different!

So, basically based on your code your expecting the SAME MDB instance to handle the redelivery:


 Integer msgId = Integer.valueOf(parsedText);
                  Integer msgCount = receivedMessages.get(msgId);
                  if (msgCount == null) {
                     msgCount = 0;
                  }
                  
                  receivedMessages.put(msgId, ++msgCount);


This simply is not going to work since two different MDB instances processed the message, although the second instance handled the REDELIVERY not the initial DELIVERY. This is not two MDB's processing the same message at the same time. The Exception forced the redelivery and a result the second MDB instance handled it the next time around. You can almost be guaranteed that the same MDB instance won't be the handling the redelivery of the message.


So, I think this solves the issue. Again, you are free to use my parser to do more testing. However, your ServletTest code I can now see why you think this was an issue when in reality it is not. 


If this explanation is sufficient, please close this BZ.

Comment 33 Weston M. Price 2011-09-06 01:00:36 UTC
Something was still bugging me. In some of my test runs, I wasn't seeing the correct total number of redelivered messages.

Example:
   1000 / 5 = 200

or even more conservative

   200 / 5 = 40


After a couple shots of expresso I started running various tests using different maxSessions settings, analyzing the results, etc. I have seen, much like you, widely varying behavior on redelivery. Sometimes there are less messages re-delivered that expected, sometimes there are more. Sending 100 messages seems to behave the most consistent in showing that 20 messages are redelivered all of the time. 

So, I think this really is a bug. However, this does not really involve the JCA code per se but is in either the Java JMS client, or in the Broker itself (I have a feeling this might be related to the DTX code on the Broker, but that is just a guess). JCA is simply a wrapper around the underlying JMS client and does not control message delivery/redelivery etc. 

So, what we are going to need to do is most likely file this with another component in the system (i.e. Java client, Broker etc) to get more eyes on the problem, or at the very least the 'correct' eyes in terms of which code is responsible. 

So, in sum, after reworking the initial test code I was able to reproduce the behavior you are seeing fairly consistently. I have a test scenario setup, as well as the parser/analyzer to evaluate test runs which can be handed off. 

One thing that would probably improve this is that log parsing is probably not the best way to do this, though it works. The number of expected messages matches all the time. However, setting up some sort of JDBC repository for the messageID, delivery count would be more efficient and would be easier to run regression against etc. I will start thinking about this.

Comment 34 Weston M. Price 2011-09-06 02:40:04 UTC
Ok, last one for today I promise. I threw together a simple routing persist the relevant info for the message to a MySQL database which makes looking at the numbers a lot easier. I will post everything tomorrow and we can take it from there. 

Good catch by the way, I am showing redelivery numbers varying widely from one test run to the next.

Comment 35 Gordon Sim 2011-09-06 08:49:53 UTC
Weston, If you can capture broker logs for an incorrect or suspicious run that will be a great start at determining where and what the issue is. Start qpidd with --log-enable info+ --log-enable trace+:amqp_0_10 (and perhaps --log-to-file /tmp/qpidd.log or something to more easily capture the output). That will give us the full interaction between the JMS client/RA and the broker; I can go through that and hopefully we can start to make some more definitive statements on what is going on.

Comment 36 Martin Vecera 2011-09-06 11:35:13 UTC
You fixed the original test code for no reason. If you started the test in the way I described you would see that the message numbering is ok. Each message contains a number that starts at 0 and goes to MESSAGE_COUNT - 1. This is what is being parsed (the message is "test01 X"). 

I use different (not XA based) connection factory in the servlet and it correctly generates messages and is able to make sure that each message content have been processed and how many times. This is why I can have the hash map with keys 0..MESSAGE_COUNT - 1.

Comment 37 Weston M. Price 2011-09-06 11:52:10 UTC
Created attachment 521644 [details]
Broker log for 733383

300 messages sent. Expected 60 redeliveries, instead received 48. maxSessions for adapter 30.

Comment 38 Martin Vecera 2011-09-06 13:09:37 UTC
Please note that my case was the opposite - I received redeliveries even in case where no redelivery was required (i.e. more redeliveries than expected).

Comment 39 Weston M. Price 2011-09-06 17:57:41 UTC
Created attachment 521725 [details]
Broker log for test run

1 Session, 100 messages

Only 2 rollbacks recorded.

Comment 40 Weston M. Price 2011-09-07 00:06:57 UTC
Martin, 
  I have to apologize. Your analysis was correct and I was wrong. This is a real issue.  Sorry I was such a jerk before. This is a real win in terms of bugs, and I owe you big time. 

The team is looking at it and we hope to have something soon.

Comment 41 Martin Vecera 2011-09-07 12:18:37 UTC
No problem Weston. How could I make the reproduce more usable for you next time? How could I provide more clear information on the issue?

Comment 42 Weston M. Price 2011-09-07 12:22:08 UTC
I think the information you provided was solid. I just needed to look at it closer (eyes are getting older I think) .

Comment 43 Weston M. Price 2011-09-07 12:36:27 UTC
Also, in the interim adding:


 <config-property name="connectionURL">amqp://anonymous:@client/test?brokerlist='tcp://10.0.1.44:5672?sasl_mechs='ANONYMOUS'&amp;sync_ack='true'&amp;max_prefetch='0''</config-property>

to your broker URL will give more reasonable results than what you were seeing before. The issue is really twofold

In the underlying JMS client, we typically prefetch messages in batches for performance reasons. The problem is that when a rollback occurs in a transaction, ALL messages in the buffer are marked as 'redelivered' so, the line in the test

!(message.getJMSRedelivered()) 

prohibited the results from being accurate. Setting that max_prefetch disables prefetching (at some cost to performance of course) and the results start to look more normal. I am discussing with the team whether marking all of those messages as redelivered is accurate since imo, if a message hasn't been handed off to an application component (in our case the adapter), my thoughts are it was never delivered before and as such, shouldn't be flagged as redelivered. 

There is still another issue with the JMS client that we are looking at, but the above setting will at least get you un-stuck so you can continue testing.

Comment 44 Martin Vecera 2011-09-08 07:50:21 UTC
The condition !(message.getJMSRedelivered()) is there just to prevent throwing an exception for a single message twice.

My next task is to compare performance of MRG and JBM in EAP. So I vote for not disabling prefetching since it could have negative drawbacks...

Comment 45 Weston M. Price 2011-09-08 08:11:04 UTC
'The condition !(message.getJMSRedelivered()) is there just to prevent throwing
an exception for a single message twice.'

Right, which was absolutely the correctly thing to do. Unfortunately, as I said about the buffer, this was causing at least, so of the strange results. 

Sounds good to me about leaving off prefetching for perf testing. 

I will getting QE more updated code at some point this week as per our JCA discussions.

Comment 46 Andrew Stitcher 2011-09-22 13:30:12 UTC
This has been fixed in package qpid-java-jca-0.10-10

Comment 47 Martin Vecera 2011-10-14 13:32:41 UTC
This is still an issue with qpid-java-jca-0.10-10. Can be reproduced with the same steps as mentioned earlier.

Comment 48 Martin Vecera 2011-10-14 13:38:03 UTC
The behaviour is different in one thing - the number of extra messages seems to be predictable and is (maxSession - 1).

Comment 49 Martin Vecera 2011-10-17 07:18:57 UTC
I realized it is not that precious. Definitely, the number of wrongly redelivered messages decreased in version 0.10-10. However, it is still non-zero.

Comment 50 Weston M. Price 2011-10-19 19:59:40 UTC
The underlying issue with the JMS client issuing 'extra credits' in the context of redelivery is still present. The JMS team is aware of of this and has offered to look at the issue. The transaction issue on the JCA side has been resolved. I don't believe the JMS team is going to have time to look at this in the context of this release. As a result I am changing the component as well as the requisite flags.

Comment 51 RHEL Product and Program Management 2011-10-19 20:05:17 UTC
Development Management has reviewed and declined this request.  You may appeal
this decision by reopening this request.

Comment 52 Martin Vecera 2011-10-21 07:36:22 UTC
Please provide a link to the issue that will be investigated in the future before closing this issue.

Comment 53 Mike Harvey 2011-10-21 12:34:17 UTC
set Blocker flag to ?

Comment 59 Weston M. Price 2011-11-17 13:13:18 UTC
*** Bug 748863 has been marked as a duplicate of this bug. ***

Comment 60 Weston M. Price 2011-11-17 14:03:15 UTC
Current status of this issue:

We have found 3 issues related to this BZ. 

1) The XASessionImpl was incorrectly setting the ack mode for XA transactions. This has been addressed in

https://issues.apache.org/jira/browse/QPID-3625

Prior to this, message acknowledgment was occurring outside of transaction boundaries.


2) The prefetch setting in the JMS client appears to be broken. The setting is not being honored and as a result, the JMS client is prefetching messages when it should not be. This is causing extra messages to be consumed when it should not be the case. 

3)When using pre buffering, some component is marking ALL messages within the buffer as being redelivered. There is still some confusion as to what component (client or broker) is doing this. Rajith, myself and Gordon are still looking at this.

Comment 62 Rajith Attapattu 2011-12-02 17:43:20 UTC
The client was marking messages in it's prefetch buffer as re-delivered even though those messages were not given to the application.
This is covered in upstream via QPID-3640

A fix has been committed in upstream trunk at rev http://svn.apache.org/viewvc?view=rev&rev=1207031

Comment 65 Martin Vecera 2012-01-09 15:53:36 UTC
The fix has been verified with MRG client 0.14 and server qpid-cpp-0.14.

Comment 66 errata-xmlrpc 2012-04-30 17:52:17 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

http://rhn.redhat.com/errata/RHSA-2012-0529.html


Note You need to log in before you can comment on or make changes to this bug.