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] Commented: (AMQNET-194) Async error occurred: javax.jms.JMSException: Unmatched acknowledege when Acknowledgemode of Transactional used
Date Thu, 08 Oct 2009 19:13:52 GMT

    [ https://issues.apache.org/activemq/browse/AMQNET-194?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=54674#action_54674
] 

Mark Gellings commented on AMQNET-194:
--------------------------------------

The exception is "An item with the same key has already been added."

It's adding a command.CommandId of 7 as the key, and that key is used in the first position
of the requestMap dictionary.

Tracked tracked = stateTracker.track(command);
lock(((ICollection) requestMap).SyncRoot)
{
if(tracked != null && tracked.WaitingForResponse)
{
--->>> requestMap.Add(command.CommandId, tracked);
}
else if(tracked == null && command.ResponseRequired)
{
requestMap.Add(command.CommandId, command);
}
}

This causes the handleTransportFailure method to be fired and the connectedTransport set to
null (ITransport transport = connectedTransport.GetAndSet(null);). The iterate() method on
FailoverTask then issues doConnect():

parent.backupMutex.WaitOne();
if(parent.ConnectedTransport == null && doReconnect)
{
result = parent.doConnect();
buildBackup = false;
}

And then the restoreTransport method is called which seems to reissue all the commands for
the 65365 messages already processed. It seems like there's two things potentially problematic,
1) the commandId of 7 is being created again which triggers the error 2) the restore Transport
method resends all the commands it already sent commands for those 65535 messages.

Another question is how come the messages are tracked?  I know it has something to do with
the failover protocol/transport but seems wrong to be storing/tracking all the messages that
the broker has already deleted from the queue.

Perhaps this is fixed in NMS trunk but this is the official 1.1 version so I imagine a lot
of folks are using this. I guess my next step is figuring out how those commandIds are generated
and why it is reset back to a value of 7? Any help/thoughts appreciated... 

> 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, NativeNMSConsumerAndProducer.zip
>
>
> 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