Return-Path: X-Original-To: apmail-activemq-dev-archive@www.apache.org Delivered-To: apmail-activemq-dev-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id 45E1A75E0 for ; Thu, 11 Aug 2011 19:46:55 +0000 (UTC) Received: (qmail 1813 invoked by uid 500); 11 Aug 2011 19:46:55 -0000 Delivered-To: apmail-activemq-dev-archive@activemq.apache.org Received: (qmail 1615 invoked by uid 500); 11 Aug 2011 19:46:54 -0000 Mailing-List: contact dev-help@activemq.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@activemq.apache.org Delivered-To: mailing list dev@activemq.apache.org Received: (qmail 1605 invoked by uid 99); 11 Aug 2011 19:46:54 -0000 Received: from nike.apache.org (HELO nike.apache.org) (192.87.106.230) by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 11 Aug 2011 19:46:54 +0000 X-ASF-Spam-Status: No, hits=-2000.8 required=5.0 tests=ALL_TRUSTED,RP_MATCHES_RCVD X-Spam-Check-By: apache.org Received: from [140.211.11.116] (HELO hel.zones.apache.org) (140.211.11.116) by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 11 Aug 2011 19:46:49 +0000 Received: from hel.zones.apache.org (hel.zones.apache.org [140.211.11.116]) by hel.zones.apache.org (Postfix) with ESMTP id 659C6B8572 for ; Thu, 11 Aug 2011 19:46:27 +0000 (UTC) Date: Thu, 11 Aug 2011 19:46:27 +0000 (UTC) From: "Timothy Bish (JIRA)" To: dev@activemq.apache.org Message-ID: <1907227289.29860.1313091987413.JavaMail.tomcat@hel.zones.apache.org> Subject: [jira] [Closed] (AMQ-2362) ActiveMQ5.2 - Some listeners stopped getting messages. Even after restart of the broker/client the messages were not getting picked. Then we stopped ActiveMQ 5.2 and started Active mq 4.1 (we migrated some one week back) and then client and it worked MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 7bit X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 X-Virus-Checked: Checked by ClamAV on apache.org [ https://issues.apache.org/jira/browse/AMQ-2362?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ] Timothy Bish closed AMQ-2362. ----------------------------- Resolution: Cannot Reproduce Reopen if problem still exists. > ActiveMQ5.2 - Some listeners stopped getting messages. Even after restart of the broker/client the messages were not getting picked. Then we stopped ActiveMQ 5.2 and started Active mq 4.1 (we migrated some one week back) and then client and it worked > ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- > > Key: AMQ-2362 > URL: https://issues.apache.org/jira/browse/AMQ-2362 > Project: ActiveMQ > Issue Type: Bug > Components: Broker > Affects Versions: 5.2.0 > Environment: linux 32 bit -2.6.18-92.el5 i686 i686 i386 GNU/Linux-, jre1.6.0_10 > Reporter: Kanonymous > Fix For: 5.6.0 > > > This seems to be a very wierd issue which came on the production env. > Set up- we are using one broker which is in our inside zone and many producers and consumers started in different applications,both in the internal zone and in the DMZ, to connect to the broker. > We were using 4.1 active mq till last week on our production enviornment and were having some issues with the number of connections sometimes were getting increased and hence after quite a bit of testing we tried to move to the 5.2 active mq. So we migrated on Monday 17Aug at around 0500 hours IST and it worked fine till Friday 0840 hours IST and after that some listeners stopped working. The consumers were showing connected but they were not receiving any message from the broker. At the same time we saw some exception like this in the broker (please note - we used journal with jdbc) > -------------------------------------------------------- > :23 JournalPersistenceAdapter - Failed to mark the Journal: org.apache.activeio.journal.InvalidRecordLocationException: The > location is less than the last mark. > org.apache.activeio.journal.InvalidRecordLocationException: The location is less than the last mark. > at org.apache.activeio.journal.active.JournalImpl.setMark(JournalImpl.java:340) > at org.apache.activemq.store.journal.JournalPersistenceAdapter.doCheckpoint(JournalPersistenceAdapter.java:416) > at org.apache.activemq.store.journal.JournalPersistenceAdapter$1.iterate(JournalPersistenceAdapter.java:121) > at org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:122) > at org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:43) > at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source) > at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) > at java.lang.Thread.run(Unknown Source) > --------------------------------------------------------------------------------------------------------- > We then restarted the broker a few times (even deleted the journal and the mesasges from DB as we did not wanted to process old messages in the system) and then this started working. Now a problem of duplicate messages started coming and checking for the net we got one fuse solution.."5.2.0.1-fuse" and we patched this release at around 1730 Hours Friday 21 Aug IST. Also for checking purpose we also changed our persistent strategy to AMP > using the following > > > > > . This worked fine (note- with considerable better performance) till around 2345 hours Friday 21 Aug IST and then again we started facing the same read location issue and our listeners stopped getting message. (Please note - Not all the listeners stopped. Somehow only the listeners in the DMZ zone stopped. In the same application the producers (based on the pooled connection factory) were working fine. Again in the broker the same error was being seen > ------------------------------------------------------------------------------------------------------------- > :23 JournalPersistenceAdapter - Failed to mark the Journal: org.apache.activeio.journal.InvalidRecordLocationException: The > location is less than the last mark. > org.apache.activeio.journal.InvalidRecordLocationException: The location is less than the last mark. > at org.apache.activeio.journal.active.JournalImpl.setMark(JournalImpl.java:340) > at org.apache.activemq.store.journal.JournalPersistenceAdapter.doCheckpoint(JournalPersistenceAdapter.java:416) > at org.apache.activemq.store.journal.JournalPersistenceAdapter$1.iterate(JournalPersistenceAdapter.java:121) > at org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:122) > at org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:43) > at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source) > at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) > at java.lang.Thread.run(Unknown Source) > ------------------------------------------------------------------------------------------------------------------------------------------------ > Now we tried to restart the broker but we got some OOM issues - probably because of the Amq persistence Adapter and hence we reverted back to our normal journal and jdbc approach and started the broker. Our listener then connected fine and started working. This was around 0300hours IST on Saturday 22 Aug. It worked fine perfectly till about Saturday 22 Aug 2345 hours IST when again we started seeing the following errors in the broker > ---------------------------------------------------------------------------------------------------------------------------------------------- > [ERROR] 00:12:22 JournalPersistenceAdapter - Failed to mark the Journal: org.apache.activeio.journal.InvalidRecordLocationException: The location is less than the last mark. > INFO | jvm 1 | 2009/08/23 00:12:23 | org.apache.activeio.journal.InvalidRecordLocationException: The location is less than the last mark. > INFO | jvm 1 | 2009/08/23 00:12:23 | at org.apache.activeio.journal.active.JournalImpl.setMark(JournalImpl.java:340) > INFO | jvm 1 | 2009/08/23 00:12:23 | at org.apache.activemq.store.journal.JournalPersistenceAdapter.doCheckpoint(JournalPersistenceAdapter.java:416) > INFO | jvm 1 | 2009/08/23 00:12:23 | at org.apache.activemq.store.journal.JournalPersistenceAdapter$1.iterate(JournalPersistenceAdapter.java:121) > INFO | jvm 1 | 2009/08/23 00:12:23 | at org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:122) > INFO | jvm 1 | 2009/08/23 00:12:23 | at org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:43) > INFO | jvm 1 | 2009/08/23 00:12:23 | at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source) > INFO | jvm 1 | 2009/08/23 00:12:23 | at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) > INFO | jvm 1 | 2009/08/23 00:12:23 | at java.lang.Thread.run(Unknown Source) > INFO | jvm 1 | 2009/08/23 00:12:23 | [ERROR] 00:12:23 JournalPersistenceAdapter - Failed to mark the Journal: org.apache.activeio.journal.InvalidRecordLocationException: The location is less than the last mark. > INFO | jvm 1 | 2009/08/23 00:12:23 | org.apache.activeio.journal.InvalidRecordLocationException: The location is less than the last mark. > INFO | jvm 1 | 2009/08/23 00:12:23 | at org.apache.activeio.journal.active.JournalImpl.setMark(JournalImpl.java:340) > INFO | jvm 1 | 2009/08/23 00:12:23 | at org.apache.activemq.store.journal.JournalPersistenceAdapter.doCheckpoint(JournalPersistenceAdapter.java:416) > INFO | jvm 1 | 2009/08/23 00:12:23 | at org.apache.activemq.store.journal.JournalPersistenceAdapter$1.iterate(JournalPersistenceAdapter.java:121) > INFO | jvm 1 | 2009/08/23 00:12:23 | at org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:122) > INFO | jvm 1 | 2009/08/23 00:12:23 | at org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:43) > INFO | jvm 1 | 2009/08/23 00:12:23 | at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source) > INFO | jvm 1 | 2009/08/23 00:12:23 | at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) > INFO | jvm 1 | 2009/08/23 00:12:23 | at java.lang.Thread.run(Unknown Source) > -------------------------------------------------------------------------------------------------------------------------------------------------------------------- > and again our listeners stopped picking up messages. Now again we tried to restart the broker and then the client but to no avail. Even we tried to put the broker on the debug mode (logging) and see if we get any errors but none were seen. By the ways the listener did not started picking up the message. So in such desparate situations we tried the following things > a) Restarting broker and client again and again - but to no avail > b) change back to Amq persistent stragtegy but again to no avail - we got this log in the broker log file > ------------------------------------- > INFO | jvm 1 | 2009/08/23 02:36:01 | [ERROR] 02:36:01 AbstractStoreCursor - Failed to fill batch > INFO | jvm 1 | 2009/08/23 02:36:01 | java.io.IOException: Failed to read to journal for: offset = 692, file = 1, size = 0, type = 0. Reason: java.io.IOException: Invalid location: offset = 692, file = 1, size = 0, type = 0, : java.lang.NegativeArraySizeException > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.util.IOExceptionSupport.create(IOExceptionSupport.java:33) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.store.amq.AMQPersistenceAdapter.createReadException(AMQPersistenceAdapter.java:647) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.store.amq.AMQPersistenceAdapter.readCommand(AMQPersistenceAdapter.java:533) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.store.amq.AMQMessageStore.getMessage(AMQMessageStore.java:435) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.store.amq.RecoveryListenerAdapter.recoverMessageReference(RecoveryListenerAdapter.java:54) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.store.kahadaptor.KahaReferenceStore.recoverReference(KahaReferenceStore.java:82) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.store.kahadaptor.KahaReferenceStore.recoverNextMessages(KahaReferenceStore.java:120) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.store.amq.AMQMessageStore.recoverNextMessages(AMQMessageStore.java:533) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.broker.region.cursors.QueueStorePrefetch.doFillBatch(QueueStorePrefetch.java:75) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:227) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.reset(AbstractStoreCursor.java:100) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.broker.region.cursors.StoreQueueCursor.reset(StoreQueueCursor.java:157) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.broker.region.Queue.doPageIn(Queue.java:1179) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.broker.region.Queue.addSubscription(Queue.java:237) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.broker.region.AbstractRegion.addConsumer(AbstractRegion.java:275) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.broker.region.RegionBroker.addConsumer(RegionBroker.java:372) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.broker.BrokerFilter.addConsumer(BrokerFilter.java:86) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.broker.BrokerFilter.addConsumer(BrokerFilter.java:86) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.advisory.AdvisoryBroker.addConsumer(AdvisoryBroker.java:83) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.broker.BrokerFilter.addConsumer(BrokerFilter.java:86) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.broker.MutableBrokerFilter.addConsumer(MutableBrokerFilter.java:93) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.broker.TransportConnection.processAddConsumer(TransportConnection.java:541) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.command.ConsumerInfo.visit(ConsumerInfo.java:345) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:305) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:179) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:68) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:143) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.transport.InactivityMonitor.onCommand(InactivityMonitor.java:206) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:84) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:203) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:185) > INFO | jvm 1 | 2009/08/23 02:36:01 | at java.lang.Thread.run(Unknown Source) > INFO | jvm 1 | 2009/08/23 02:36:01 | Caused by: java.io.IOException: Invalid location: offset = 692, file = 1, size = 0, type = 0, : java.lang.NegativeArraySizeException > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.kaha.impl.async.DataFileAccessor.readRecord(DataFileAccessor.java:94) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.kaha.impl.async.AsyncDataManager.read(AsyncDataManager.java:624) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.store.amq.AMQPersistenceAdapter.readCommand(AMQPersistenceAdapter.java:530) > INFO | jvm 1 | 2009/08/23 02:36:01 | ... 29 more > INFO | jvm 1 | 2009/08/23 02:36:01 | [ERROR] 02:36:01 AbstractStoreCursor - Failed to fill batch > INFO | jvm 1 | 2009/08/23 02:36:01 | java.lang.RuntimeException: java.io.IOException: Failed to read to journal for: offset = 692, file = 1, size = 0, type = 0. Reason: java.io.IOException: Invalid location: offset = 692, file = 1, size = 0, type = 0, : java.lang.NegativeArraySizeException > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:230) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.reset(AbstractStoreCursor.java:100) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.broker.region.cursors.StoreQueueCursor.reset(StoreQueueCursor.java:157) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.broker.region.Queue.doPageIn(Queue.java:1179) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.broker.region.Queue.addSubscription(Queue.java:237) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.broker.region.AbstractRegion.addConsumer(AbstractRegion.java:275) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.broker.region.RegionBroker.addConsumer(RegionBroker.java:372) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.broker.BrokerFilter.addConsumer(BrokerFilter.java:86) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.broker.BrokerFilter.addConsumer(BrokerFilter.java:86) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.advisory.AdvisoryBroker.addConsumer(AdvisoryBroker.java:83) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.broker.BrokerFilter.addConsumer(BrokerFilter.java:86) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.broker.MutableBrokerFilter.addConsumer(MutableBrokerFilter.java:93) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.broker.TransportConnection.processAddConsumer(TransportConnection.java:541) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.command.ConsumerInfo.visit(ConsumerInfo.java:345) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:305) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:179) > INFO | jvm 1 | 2009/08/23 02:36:01 | at org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:68) > INFO | jvm 1 | 2009/08/23 02:36:01 | > ---------------------------------------------------------------------------------- > Now it was around 0300 hours on Sunday 23 Aug IST and we were loosing time. So just in some silly mind we tried to revert back to 4.1 Active mq leaving other things untouched..And to a matter of disbeleif it started working. And the listeners started picking up messages (Even old one from the DB were picked - whcih means 5.2 is backward compliant as well) and it worked fine. > We are now seriously considering not to take any change with any other version of Active MQ other than 4.1. Please advice if we are doing somehting wrong here. Also i am attaching both my activemq.xml from 5.2 and 4.1 -- This message is automatically generated by JIRA. For more information on JIRA, see: http://www.atlassian.com/software/jira