activemq-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Kush Srivastava (JIRA)" <j...@apache.org>
Subject [jira] Updated: (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
Date Sat, 22 Aug 2009 23:14:36 GMT

     [ https://issues.apache.org/activemq/browse/AMQ-2362?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]

Kush Srivastava updated AMQ-2362:
---------------------------------

    Summary: 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  (was: 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)

> 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/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.


Mime
View raw message