Mailing-List: contact users-help@activemq.apache.org; run by ezmlm
Precedence: bulk
Reply-To: users@activemq.apache.org
Received-SPF: pass (nike.apache.org: domain of lists@nabble.com designates
 216.139.236.158 as permitted sender)
Message-ID: <25960021.post@talk.nabble.com>
Date: Mon, 19 Oct 2009 08:10:31 -0700 (PDT)
From: Daniel Ellis <mail@danellis.co.uk>
To: users@activemq.apache.org
Subject: Re: Async error occurred -> ActiveMQ 5.2 and NMS
In-Reply-To: <25721340.post@talk.nabble.com>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Transfer-Encoding: 7bit
References: <25474605.post@talk.nabble.com> <25515100.post@talk.nabble.com>
 <25619079.post@talk.nabble.com> <25721340.post@talk.nabble.com>


We have also experienced this issue when using ActiveMQ 1.2 with NMS.

On the server, the wrapper.log file is full of these errors:-

INFO   | jvm 1    | 2009/10/17 13:07:00 | ERROR Service                       
- Async error occurred: javax.jms.JMSException: Unmatched acknowledege:
MessageAck {commandId = 149, responseRequired = false, ackType = 2,
consumerId = dcfc7fed-2e32-49eb-923e-a823b0151117:12:1, firstMessageId =
dcfc7fed-2e32-49eb-923e-a823b0151117:1:2:1, lastMessageId =
dcfc7fed-2e32-49eb-923e-a823b0151117:1:2:1, destination =
queue://Progression.Scheduler, transactionId =
TX:dcfc7fed-2e32-49eb-923e-a823b0151117:1, messageCount = 1}; Could not find
Message-ID dcfc7fed-2e32-49eb-923e-a823b0151117:1:2:1 in dispatched-list
(start of ack)
INFO   | jvm 1    | 2009/10/17 13:07:00 | javax.jms.JMSException: Unmatched
acknowledege: MessageAck {commandId = 149, responseRequired = false, ackType
= 2, consumerId = dcfc7fed-2e32-49eb-923e-a823b0151117:12:1, firstMessageId
= dcfc7fed-2e32-49eb-923e-a823b0151117:1:2:1, lastMessageId =
dcfc7fed-2e32-49eb-923e-a823b0151117:1:2:1, destination =
queue://Progression.Scheduler, transactionId =
TX:dcfc7fed-2e32-49eb-923e-a823b0151117:1, messageCount = 1}; Could not find
Message-ID dcfc7fed-2e32-49eb-923e-a823b0151117:1:2:1 in dispatched-list
(start of ack)
INFO   | jvm 1    | 2009/10/17 13:07:00 |       at..................

On the client we see the log full with:-

Apache.NMS.NMSConnectionException: Unmatched acknowledege: MessageAck
{commandId = -4156, responseRequired = false, ackType = 2, consumerId =
dcfc7fed-2e32-49eb-923e-a823b0151117:12:1, firstMessageId =
dcfc7fed-2e32-49eb-923e-a823b0151117:1:2:5061, lastMessageId =
dcfc7fed-2e32-49eb-923e-a823b0151117:1:2:5061, destination =
queue://Progression.Scheduler, transactionId =
TX:dcfc7fed-2e32-49eb-923e-a823b0151117:5028, messageCount = 1}; Could not
find Message-ID dcfc7fed-2e32-49eb-923e-a823b0151117:1:2:5061 in
dispatched-list (start of ack)

I think this may be due to incorrect handling in the failover transport of
NMS.  My guess is that the failover transport is handling the exception by
reconnecting, and then attempting to perform the exact same command which is
causing the same exception to occur, and round and round it goes %-|.


magellings wrote:
> 
> I captured some stats from the broker before after this happened...
> 
>  http://www.nabble.com/file/p25721340/stats2.txt Before 
>  http://www.nabble.com/file/p25721340/stats5.txt After 
> 
> Does anyone see any stat that sticks out as a problem?
> 
> 
> magellings wrote:
>> 
>> I found something interesting.
>> 
>> If I remove delete privs on the ACTIVEMQ_MSGS TABLE (we're doing JDBC
>> Master/Slave) there are a couple things happening...
>> 
>> #1) I receive Async errors to the looks of it the same as before.
>> #2) The same messages are getting delivered to the listener after a
>> restart of the broker despite the fact the consumer already processed
>> them successfully.
>> 
>> What I'm wondering is if maybe there's is some sort of hiccup with Sql
>> Server during our high throughput tests and it wreaks havoc.
>> 
>> 2009-09-25 15:47:57,176 [//10.0.1.5:4831] ERROR Service                       
>> - Async error occurred: javax.jms.JMSException: Unmatched acknowledege:
>> MessageAck {commandId = 788, responseRequired = false, ackType = 2,
>> consumerId = 34be0700-62a7-4594-9ce3-decfe067be28:1:1, firstMessageId =
>> 7a67e547-4dea-4ee5-9c4d-0460f3d2c005:1:1:61, lastMessageId =
>> 7a67e547-4dea-4ee5-9c4d-0460f3d2c005:1:1:61, destination =
>> queue://testme, transactionId =
>> TX:34be0700-62a7-4594-9ce3-decfe067be28:262, messageCount = 1}; Could not
>> find Message-ID 7a67e547-4dea-4ee5-9c4d-0460f3d2c005:1:1:61 in
>> dispatched-list (start of ack)
>> javax.jms.JMSException: Unmatched acknowledege: MessageAck {commandId =
>> 788, responseRequired = false, ackType = 2, consumerId =
>> 34be0700-62a7-4594-9ce3-decfe067be28:1:1, firstMessageId =
>> 7a67e547-4dea-4ee5-9c4d-0460f3d2c005:1:1:61, lastMessageId =
>> 7a67e547-4dea-4ee5-9c4d-0460f3d2c005:1:1:61, destination =
>> queue://testme, transactionId =
>> TX:34be0700-62a7-4594-9ce3-decfe067be28:262, messageCount = 1}; Could not
>> find Message-ID 7a67e547-4dea-4ee5-9c4d-0460f3d2c005:1:1:61 in
>> dispatched-list (start of ack)
>> 	at
>> org.apache.activemq.broker.region.PrefetchSubscription.assertAckMatchesDispatched(PrefetchSubscription.java:438)
>> 	at
>> org.apache.activemq.broker.region.PrefetchSubscription.acknowledge(PrefetchSubscription.java:188)
>> 	at
>> org.apache.activemq.broker.region.AbstractRegion.acknowledge(AbstractRegion.java:373)
>> 	at
>> org.apache.activemq.broker.region.RegionBroker.acknowledge(RegionBroker.java:462)
>> 	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.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:456)
>> 	at org.apache.activemq.command.MessageAck.visit(MessageAck.java:205)
>> 	at
>> org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:305)
>> 	at
>> org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:179)
>> 	at
>> org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:68)
>> 	at
>> org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:143)
>> 	at
>> org.apache.activemq.transport.InactivityMonitor.onCommand(InactivityMonitor.java:206)
>> 	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)
>> 
>> 
>> 
>> magellings wrote:
>>> 
>>> I was able to replicate this problem and am attaching a console
>>> application written with .NET/VS 2008 using the official NMS 1.1.
>>> provider.  We are using ActiveMQ 5.2 with same config file as I attached
>>> previously.
>>> 
>>> To replicate send 1,000,000 messages through.  Make a copy of the
>>> console application in "Debug" to a separate directory and run the
>>> producer and consumer in separate applications.  Enter 0 for a pace with
>>> producer.  
>>> 
>>>  http://www.nabble.com/file/p25515100/NativeNMSConsumerAndProducer.zip
>>> NativeNMSConsumerAndProducer.zip 
>>> 
>>> The Async error occurs around 650,000 msgs and producer, consumer, and
>>> broker does not recover.  One can use Sql Server Express to set up the
>>> database needed for jdbc master/slave.  I did not test in another
>>> master/slave configuration.
>>> 
>>> 
>>> 
>>> 
>>> magellings wrote:
>>>> 
>>>> Hello.  We are stress testing ActiveMQ 5.2 using NMS for .NET
>>>> producers/consumers.  We are sending 200,000 messages through our
>>>> system and we ran into the error "Async error occurred" shortened for
>>>> brevity.  Log file is attached.  It seems this error keeps reoccuring
>>>> after the first one and fills the wrapper.log file to 29GB before disk
>>>> space fills up and broker stops working.  We are running the broker in
>>>> a windows service on Windows Server 2008.
>>>> 
>>>> Can anyone take a look at the log file and provide me input into what
>>>> the problem is?  Or some suggestions on modifying our activemq.xml
>>>> configuration.  I'm thinking of setting our prefetch higher than 5 for
>>>> our consumers.  With the thought this will reduce network activity
>>>> between the broker and consumers.
>>>> 
>>>> a log with a snippet of the exceptions and activemq.xml attached.  
>>>> 
>>>> Thoughts?
>>>> 
>>>>  http://www.nabble.com/file/p25474605/activemq.xml activemq.xml 
>>>>  http://www.nabble.com/file/p25474605/LogSnippet.txt LogSnippet.txt 
>>>> 
>>> 
>>> 
>> 
>> 
> 
> 

-- 
View this message in context: http://www.nabble.com/Async-error-occurred--%3E-ActiveMQ-5.2-and-NMS-tp25474605p25960021.html
Sent from the ActiveMQ - User mailing list archive at Nabble.com.