ActiveMQ5.2 - Some consumer stopped listining in prod env. 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/activemq/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: Kush Srivastava
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.
