activemq-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Mark Gellings (JIRA)" <jira+amq...@apache.org>
Subject [jira] Updated: (AMQNET-194) Async error occurred: javax.jms.JMSException: Unmatched acknowledege when Acknowledgemode of Transactional used
Date Thu, 15 Oct 2009 19:27:52 GMT

     [ 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.


Mime
View raw message