[
https://issues.apache.org/activemq/browse/AMQNET-194?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Mark Gellings updated AMQNET-194:
---------------------------------
Attachment: debuggingTrunk.patch
Timothy.
I have replicated this issue with ActiveMQ 5.3 and Apache.NMS.ActiveMQ trunk.
Please do the following so as you can try and replicate the problem on your
side:
1) Apply the attached debuggingTrunk.patch to Apache.NMS.ActiveMQ trunk. This
will add Console.WriteLine's so that when you execute the test case with the
Console Application I attached earlier you can see the status of the request
map logged to the console window.
2) Extract the NativeNMSConsumerAndProducer.zip attached to this issue and open
in Visual Studio 2008.
3) Remove the vs2008-activemq and vs2008-nms projects. Reference the patched
Apache.NMS.ActiveMQ dll and Apache.NMS dll from trunk in the
ConsoleApplication1 project.
4) Comment out the following lines and build the solution (should succeed):
bq. In Send()...
bq. {color:red}
Console.WriteLine("SENDER Sent {0}/{1}: Text: {2}", (i + 1),
_sendCnt,
activeMQMessage.Text);
{color}
bq. In OnMessage(IMessage message)...
bq. {color:red} Console.WriteLine("LISTENER Message:");{color}
bq. {color:red} Console.WriteLine("LISTENER " + message);{color}
bq. In Main()...
bq. {color:red} while (true){color}
bq. {color:red} {{color}
bq. {color:red} test2 += 1;{color}
bq. {color:red} Console.WriteLine(test2);{color}
bq. {color:red} if (test2 > 65530)
Thread.Sleep(2000);{color}
bq. {color:red} }{color}
5) Start an instance of ActiveMQ 5.3 broker on the same machine you'll run the
producer/consumer NMS clients.
6) Copy the solution's ..\bin\Debug directory somewhere. Run
ConsoleApplication1.exe from the copied location. Start a producer enter values
to hit your local ActiveMQ 5.3 broker, localhost:port, etc. and send 1,000,000
messages at a pace of 0. You should see logging of the below to your console
which indicates the request map is being cleaned successfully.
bq. Removing X. Is X in requestMap? True
bq. Request map count is now 0
7) Run ConsoleApplication1 from the solution's..\bin\Debug directory. Start a
consumer with same address/port/etc. used in the producer you started (be sure
"not" to start a producer when you start the consumer). You should see logging
of the below to your console. N being the subsequent count as messages come
through from the producer.
bq. Request map count is now 1
bq. Request map count is now 2
bq. ...
bq. Request map count is now N
For me once N reaches a value of 65536 the restore is triggered in which the
consumer seems to get into an infinite loop and no more messages are processed
by that consumer.
When it gets too large, the "An item with the same key has already been added."
exception occurs in the FailoverTransport.Oneway(Command command) method when
adding to the request map.
It's my understanding the consumer's request map should have items removed from
it which seems like the root cause of the Async/unmatched exception.
Output on the consumer console is as follows at that point.
Request map count is now 65532
Request map count is now 65533
Request map count is now 65534
Request map count is now 65535
Request map count is now 65536
Request map count is now 65536
Request map count is now 65536
Request map count is now 65536
Request map count is now 65536
Request map count is now 65536
Exception Occured!!! Message: An item with the same key has already been added.
StackTrace: at System.ThrowHelper.ThrowArgumentException(ExceptionResource re
source)
at System.Collections.Generic.Dictionary`2.Insert(TKey key, TValue value, Boo
lean add)
at System.Collections.Generic.Dictionary`2.Add(TKey key, TValue value)
at Apache.NMS.ActiveMQ.Transport.Failover.FailoverTransport.Oneway(Command co
mmand) in C:\WIP\Apache.NMS.ActiveMQ\src\main\csharp\Transport\Failover\Failover
Transport.cs:line 537
Request map count is now 65536
Request map count is now 65536
Doing transaction restore...
Removing 1. Is 1 in requestMap? True
Request map count is now 65535
Removing 2. Is 2 in requestMap? True
Request map count is now 65534
Doing restore on 65537 transactionStates. Press <enter> to have NMS.ActiveMQ co
ntinue the restore.
Request map count is now 65534
Request map count is now 65534
Request map count is now 65534
Request map count is now 65534
Removing 3. Is 3 in requestMap? True
Request map count is now 65533
Request map count is now 65533
Request map count is now 65533
Request map count is now 65533
If you enable WARN logging on the ActiveMQ 5.3 broker:
bq. # When debugging or reporting problems to the ActiveMQ team,
bq. # comment out the above lines and uncomment the next.
bq. log4j.rootLogger=DEBUG, logfile, console
You should see the Async/unmatched acknowledgement exceptions after you hit
<enter> twice on the console consumer. Example:
2009-10-15 11:25:24,691 | WARN | Async error occurred: javax.jms.JMSException:
Unmatched acknowledege: MessageAck {commandId = 19576, responseRequired =
false, ackType = 2, consumerId = e7a9de6b-c49b-4c9a-bf3e-7e12a4897392:1:1,
firstMessageId = 484c7fbf-c25b-4be6-989e-b946b781a98a:1:1:28370, lastMessageId
= 484c7fbf-c25b-4be6-989e-b946b781a98a:1:1:28370, destination =
queue://hover1112, transactionId =
TX:e7a9de6b-c49b-4c9a-bf3e-7e12a4897392:28370, messageCount = 1}; Could not
find Message-ID 484c7fbf-c25b-4be6-989e-b946b781a98a:1:1:28370 in
dispatched-list (start of ack) |
org.apache.activemq.broker.TransportConnection.Service | ActiveMQ Transport:
tcp:///10.0.1.5:4843
javax.jms.JMSException: Unmatched acknowledege: MessageAck {commandId = 19576,
responseRequired = false, ackType = 2, consumerId =
e7a9de6b-c49b-4c9a-bf3e-7e12a4897392:1:1, firstMessageId =
484c7fbf-c25b-4be6-989e-b946b781a98a:1:1:28370, lastMessageId =
484c7fbf-c25b-4be6-989e-b946b781a98a:1:1:28370, destination =
queue://hover1112, transactionId =
TX:e7a9de6b-c49b-4c9a-bf3e-7e12a4897392:28370, messageCount = 1}; Could not
find Message-ID 484c7fbf-c25b-4be6-989e-b946b781a98a:1:1:28370 in
dispatched-list (start of ack)
at
org.apache.activemq.broker.region.PrefetchSubscription.assertAckMatchesDispatched(PrefetchSubscription.java:440)
at
org.apache.activemq.broker.region.PrefetchSubscription.acknowledge(PrefetchSubscription.java:208)
at
org.apache.activemq.broker.region.AbstractRegion.acknowledge(AbstractRegion.java:369)
at
org.apache.activemq.broker.region.RegionBroker.acknowledge(RegionBroker.java:470)
at
org.apache.activemq.broker.TransactionBroker.acknowledge(TransactionBroker.java:194)
at
org.apache.activemq.broker.BrokerFilter.acknowledge(BrokerFilter.java:74)
at
org.apache.activemq.broker.BrokerFilter.acknowledge(BrokerFilter.java:74)
at
org.apache.activemq.broker.MutableBrokerFilter.acknowledge(MutableBrokerFilter.java:85)
at
org.apache.activemq.broker.TransportConnection.processMessageAck(TransportConnection.java:449)
at org.apache.activemq.command.MessageAck.visit(MessageAck.java:205)
at
org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:297)
at
org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:175)
at
org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:68)
at
org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:113)
at
org.apache.activemq.transport.InactivityMonitor.onCommand(InactivityMonitor.java:210)
at
org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:84)
at
org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:203)
at
org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:185)
at java.lang.Thread.run(Unknown Source)
> Async error occurred: javax.jms.JMSException: Unmatched acknowledege when
> Acknowledgemode of Transactional used
> ---------------------------------------------------------------------------------------------------------------
>
> Key: AMQNET-194
> URL: https://issues.apache.org/activemq/browse/AMQNET-194
> Project: ActiveMQ .Net
> Issue Type: Bug
> Components: ActiveMQ, NMS
> Affects Versions: 1.0.0, 1.1.0
> Environment: ActiveMQ 5.2 as Windows Service on Windows Server 2008
> 64-bit. Client producer and consumer on Windows XP
> Reporter: Mark Gellings
> Assignee: Timothy Bish
> Fix For: 1.2.0
>
> Attachments: activemq.xml, CropperCapture[61].jpg,
> CropperCapture[62].jpg, CropperCapture[63].jpg, debugging.patch,
> debuggingTrunk.patch, NativeNMSConsumerAndProducer.zip,
> screenshot-of-captured-exception.jpg
>
>
> See
> http://www.nabble.com/Async-error-occurred--%3E-ActiveMQ-5.2-and-NMS-td25474605.html
> for a primer to this issue.
> After troubleshooting this, it appears that if a producer sends 65535+
> messages to the broker that the consumer gets into an infinite loop after
> consuming 65535 messages.
> I will be attaching a test case for this. Run a producer and a consumer,
> send 100,000 messages and the test case fails at 65535 messages consumed
> exactly.
> What appears to be happening is that the NMS provider (or ActiveMQ 5.2) is
> hitting the upper bound of a ushort and then starting all back over again
> sending message acknowledgements from message #1. This message was already
> dispatched though and the broker lot shows an error that the message is not
> in the dispatched-list .
> The consumer shows a message acknowledgement going out.
> These errors repeat infinitely it seems. Once the 65535th message errors out
> then it starts all over again at the 1st message.
> Notice the ProducerSequenceId growing beyond 65535. I can't seem to avoid
> this error, even if I reinstantiate the producer sporadically.
> At the beginning of the source code I have included a loop which shows the
> behavior of incrementing a ushort beyond 65535. The variable resets to the
> lower bound as expected.
> [DEBUG] Apache.NMS.Tracer - Sending Ack: MessageAck[
> Destination=queue://testmonday150 TransactionId=LocalTransactionId[
> Value=30558 ConnectionId=ConnectionId[
> Value=2b6ae5a1-c0e1-4523-8d9c-4143cc9d74e8 ] ] ConsumerId=ConsumerId[
> ConnectionId=2b6ae5a1-c0e1-4523-8d9c-4143cc9d74e8 SessionId=1 Value=1 ]
> AckType=2 FirstMessageId=MessageId[ ProducerId=ProducerId[
> ConnectionId=9e256437-df18-44e5-9cb2-b7f3feaebcfd Value=1 SessionId=1 ]
> ProducerSequenceId=30558 BrokerSequenceId=80280 ] LastMessageId=MessageId[
> ProducerId=ProducerId[ ConnectionId=9e256437-df18-44e5-9cb2-b7f3feaebcfd
> Value=1 SessionId=1 ] ProducerSequenceId=30558 BrokerSequenceId=80280 ]
> MessageCount=1 ]
> ERROR Service -
> Async error occurred: javax.jms.JMSException: Unmatched acknowledege:
> MessageAc
> k {commandId = 26140, responseRequired = false, ackType = 2, consumerId =
> 41b092
> 97-da4b-4d11-9ed7-09d344825740:1:1, firstMessageId =
> 4128971e-c69b-4892-8be5-d99
> 868045881:1:1:30558, lastMessageId =
> 4128971e-c69b-4892-8be5-d99868045881:1:1:30
> 558, destination = queue://testwed924, transactionId =
> TX:41b09297-da4b-4d11-9ed
> 7-09d344825740:30558, messageCount = 1}; Could not find Message-ID
> 4128971e-c69b
> -4892-8be5-d99868045881:1:1:30558 in dispatched-list (start of ack)
> INFO | jvm 1 | 2009/10/07 14:03:27 | javax.jms.JMSException: Unmatched
> ackn
> owledege: MessageAck {commandId = 26140, responseRequired = false, ackType =
> 2,
> consumerId = 41b09297-da4b-4d11-9ed7-09d344825740:1:1, firstMessageId =
> 4128971e
> -c69b-4892-8be5-d99868045881:1:1:30558, lastMessageId =
> 4128971e-c69b-4892-8be5-
> d99868045881:1:1:30558, destination = queue://testwed924, transactionId =
> TX:41b
> 09297-da4b-4d11-9ed7-09d344825740:30558, messageCount = 1}; Could not find
> Messa
> ge-ID 4128971e-c69b-4892-8be5-d99868045881:1:1:30558 in dispatched-list
> (start o
> f ack)
> INFO | jvm 1 | 2009/10/07 14:03:27 | at
> org.apache.activemq.broker.re
> gion.PrefetchSubscription.assertAckMatchesDispatched(PrefetchSubscription.java:4
> 38)
> INFO | jvm 1 | 2009/10/07 14:03:27 | at
> org.apache.activemq.broker.re
> gion.PrefetchSubscription.acknowledge(PrefetchSubscription.java:188)
> INFO | jvm 1 | 2009/10/07 14:03:27 | at
> org.apache.activemq.broker.re
> gion.AbstractRegion.acknowledge(AbstractRegion.java:373)
> INFO | jvm 1 | 2009/10/07 14:03:27 | at
> org.apache.activemq.broker.re
> gion.RegionBroker.acknowledge(RegionBroker.java:462)
> INFO | jvm 1 | 2009/10/07 14:03:27 | at
> org.apache.activemq.broker.Tr
> ansactionBroker.acknowledge(TransactionBroker.java:194)
> INFO | jvm 1 | 2009/10/07 14:03:27 | at
> org.apache.activemq.broker.Br
> okerFilter.acknowledge(BrokerFilter.java:74)
> INFO | jvm 1 | 2009/10/07 14:03:27 | at
> org.apache.activemq.broker.Br
> okerFilter.acknowledge(BrokerFilter.java:74)
> INFO | jvm 1 | 2009/10/07 14:03:27 | at
> org.apache.activemq.broker.Br
> okerFilter.acknowledge(BrokerFilter.java:74)
> INFO | jvm 1 | 2009/10/07 14:03:27 | at
> org.apache.activemq.broker.Br
> okerFilter.acknowledge(BrokerFilter.java:74)
> INFO | jvm 1 | 2009/10/07 14:03:27 | at
> org.apache.activemq.broker.Mu
> tableBrokerFilter.acknowledge(MutableBrokerFilter.java:85)
> INFO | jvm 1 | 2009/10/07 14:03:27 | at
> org.apache.activemq.broker.Tr
> ansportConnection.processMessageAck(TransportConnection.java:456)
> INFO | jvm 1 | 2009/10/07 14:03:27 | at
> org.apache.activemq.command.M
> essageAck.visit(MessageAck.java:205)
> INFO | jvm 1 | 2009/10/07 14:03:27 | at
> org.apache.activemq.broker.Tr
> ansportConnection.service(TransportConnection.java:305)
> INFO | jvm 1 | 2009/10/07 14:03:27 | at
> org.apache.activemq.broker.Tr
> ansportConnection$1.onCommand(TransportConnection.java:179)
> INFO | jvm 1 | 2009/10/07 14:03:27 | at
> org.apache.activemq.transport
> .TransportFilter.onCommand(TransportFilter.java:68)
> INFO | jvm 1 | 2009/10/07 14:03:27 | at
> org.apache.activemq.transport
> .WireFormatNegotiator.onCommand(WireFormatNegotiator.java:143)
> INFO | jvm 1 | 2009/10/07 14:03:27 | at
> org.apache.activemq.transport
> .InactivityMonitor.onCommand(InactivityMonitor.java:206)
> INFO | jvm 1 | 2009/10/07 14:03:27 | at
> org.apache.activemq.transport
> .TransportSupport.doConsume(TransportSupport.java:84)
> INFO | jvm 1 | 2009/10/07 14:03:27 | at
> org.apache.activemq.transport
> .tcp.TcpTransport.doRun(TcpTransport.java:203)
> INFO | jvm 1 | 2009/10/07 14:03:27 | at
> org.apache.activemq.transport
> .tcp.TcpTransport.run(TcpTransport.java:185)
> INFO | jvm 1 | 2009/10/07 14:03:27 | at
> java.lang.Thread.run(Unknown
> Source)
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
