[
https://issues.apache.org/jira/browse/AMQ-2362?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Dejan Bosanac updated AMQ-2362:
-------------------------------
Fix Version/s: (was: 5.4.2)
5.5.0
> 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.5.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
> <persistenceAdapter>
> <amqPersistenceAdapter syncOnWrite="false"
> directory="./activemq-data" maxFileLength="100 mb"/>
> </persistenceAdapter>
>
> . 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.
-
You can reply to this email to add a comment to the issue online.
