Unable to pick up messages anymore, messages are lost - Looking for key xyz but
not found in fileMap
----------------------------------------------------------------------------------------------------
Key: AMQ-3470
URL: https://issues.apache.org/jira/browse/AMQ-3470
Project: ActiveMQ
Issue Type: Bug
Environment: Used from .NET 4.0
Apache.NMS.ActiveMQ.dll - 1.5.1.2341
Apache.NMS.dll - 1.5.0.2194
ActiveMQ - 5.5.0
Reporter: Frank Gynnild
Priority: Blocker
We've a C# test client that constantly produces and consumes messages of
various sizes.
After successfully sending and receiving about 5.5 million messages, ActiveMQ
enters
a certain state where:
- No more messages in the queue cannot be dequeued/received.
- Looking at the ActiveMQ browser, we're no longer able to see the message.
- The logs get filled up and rotate at a crazy pace.
- We aren't able to recover after this, restarting the ActiveMQ doesn't help.
We haven't been able to consistently reproduce this behavior, it can happen
after
any numbers of messages (usually after some million messages). Last it took
about 8
hours before we could come into this stage.
The tests are very basic.
I've been able to catch the log when this happens:
---
2011-08-22 11:13:50,919 | INFO | Refreshing
org.apache.activemq.xbean.XBeanBrokerFactory$1@3479e304: startup date [Mon Aug
22 11:13:50 CEST 2011]; root of context hierarchy |
org.apache.activemq.xbean.XBeanBrokerFactory$1 | main
2011-08-22 11:13:54,638 | WARN | destroyApplicationContextOnStop parameter is
deprecated, please use shutdown hooks instead |
org.apache.activemq.xbean.XBeanBrokerService | main
2011-08-22 11:13:54,645 | INFO |
PListStore:C:\ActiveMQ\data\IES_CARMINE\tmp_storage started |
org.apache.activemq.store.kahadb.plist.PListStore | main
2011-08-22 11:13:54,723 | INFO | Using Persistence Adapter:
KahaDBPersistenceAdapter[C:\ActiveMQ\data\kahadb] |
org.apache.activemq.broker.BrokerService | main
2011-08-22 11:13:54,932 | INFO | ActiveMQ 5.5.0 JMS Message Broker
(IES_CARMINE) is starting | org.apache.activemq.broker.BrokerService | main
2011-08-22 11:13:54,933 | INFO | For help or more information please see:
http://activemq.apache.org/ | org.apache.activemq.broker.BrokerService | main
2011-08-22 11:13:55,224 | INFO | Listening for connections at:
tcp://Carmine:61616?keepAlive=true&wireFormat.tightEncodingEnabled=false&wireFormat.cacheEnabled=false
| org.apache.activemq.transport.TransportServerThreadSupport | main
2011-08-22 11:13:55,226 | INFO | Connector openwire Started |
org.apache.activemq.broker.TransportConnector | main
2011-08-22 11:13:55,233 | INFO | ActiveMQ JMS Message Broker (IES_CARMINE,
ID:Carmine-60118-1314004434990-0:1) started |
org.apache.activemq.broker.BrokerService | main
2011-08-22 11:13:55,390 | INFO | jetty-7.1.6.v20100715 |
org.eclipse.jetty.util.log | main
2011-08-22 11:13:56,043 | INFO | ActiveMQ WebConsole initialized. |
org.apache.activemq.web.WebConsoleStarter | main
2011-08-22 11:13:56,367 | INFO | Initializing Spring FrameworkServlet
'dispatcher' | /admin | main
2011-08-22 11:13:56,807 | INFO | ActiveMQ Console at http://0.0.0.0:8161/admin
| org.eclipse.jetty.util.log | main
2011-08-22 11:13:56,852 | INFO | WebApp@280236390 at
http://0.0.0.0:8161/console | org.eclipse.jetty.util.log | main
2011-08-22 11:13:56,876 | INFO | Started [email protected]:8161 |
org.eclipse.jetty.util.log | main
2011-08-23 19:45:41,881 | ERROR | Looking for key 11856 but not found in
fileMap: {11857=db-11857.log number = 11857 , length = 1949} |
org.apache.kahadb.journal.Journal | Queue:TestQueue
2011-08-23 19:45:41,935 | ERROR | QueueStorePrefetch314000409 - Failed to fill
batch | org.apache.activemq.broker.region.cursors.AbstractStoreCursor |
Queue:TestQueue
java.io.IOException: Could not locate data file
C:\ActiveMQ\data\kahadb\db-11856.log
at org.apache.kahadb.journal.Journal.getDataFile(Journal.java:350)
at org.apache.kahadb.journal.Journal.read(Journal.java:597)
at
org.apache.activemq.store.kahadb.MessageDatabase.load(MessageDatabase.java:817)
at
org.apache.activemq.store.kahadb.KahaDBStore.loadMessage(KahaDBStore.java:955)
at
org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore$5.execute(KahaDBStore.java:493)
at org.apache.kahadb.page.Transaction.execute(Transaction.java:728)
at
org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore.recoverNextMessages(KahaDBStore.java:485)
at
org.apache.activemq.store.ProxyMessageStore.recoverNextMessages(ProxyMessageStore.java:88)
at
org.apache.activemq.broker.region.cursors.QueueStorePrefetch.doFillBatch(QueueStorePrefetch.java:97)
at
org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:260)
at
org.apache.activemq.broker.region.cursors.AbstractStoreCursor.reset(AbstractStoreCursor.java:108)
at
org.apache.activemq.broker.region.cursors.StoreQueueCursor.reset(StoreQueueCursor.java:157)
at
org.apache.activemq.broker.region.Queue.doPageInForDispatch(Queue.java:1712)
at
org.apache.activemq.broker.region.Queue.pageInMessages(Queue.java:1932)
at org.apache.activemq.broker.region.Queue.iterate(Queue.java:1440)
at
org.apache.activemq.thread.DedicatedTaskRunner.runTask(DedicatedTaskRunner.java:104)
at
org.apache.activemq.thread.DedicatedTaskRunner$1.run(DedicatedTaskRunner.java:42)
2011-08-23 19:45:41,939 | ERROR | QueueStorePrefetch314000409 - Failed to fill
batch | org.apache.activemq.broker.region.cursors.AbstractStoreCursor |
Queue:TestQueue
java.lang.RuntimeException: java.io.IOException: Could not locate data file
C:\ActiveMQ\data\kahadb\db-11856.log
at
org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:263)
at
org.apache.activemq.broker.region.cursors.AbstractStoreCursor.reset(AbstractStoreCursor.java:108)
at
org.apache.activemq.broker.region.cursors.StoreQueueCursor.reset(StoreQueueCursor.java:157)
at
org.apache.activemq.broker.region.Queue.doPageInForDispatch(Queue.java:1712)
at
org.apache.activemq.broker.region.Queue.pageInMessages(Queue.java:1932)
at org.apache.activemq.broker.region.Queue.iterate(Queue.java:1440)
at
org.apache.activemq.thread.DedicatedTaskRunner.runTask(DedicatedTaskRunner.java:104)
at
org.apache.activemq.thread.DedicatedTaskRunner$1.run(DedicatedTaskRunner.java:42)
Caused by: java.io.IOException: Could not locate data file
C:\ActiveMQ\data\kahadb\db-11856.log
at org.apache.kahadb.journal.Journal.getDataFile(Journal.java:350)
at org.apache.kahadb.journal.Journal.read(Journal.java:597)
at
org.apache.activemq.store.kahadb.MessageDatabase.load(MessageDatabase.java:817)
at
org.apache.activemq.store.kahadb.KahaDBStore.loadMessage(KahaDBStore.java:955)
at
org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore$5.execute(KahaDBStore.java:493)
at org.apache.kahadb.page.Transaction.execute(Transaction.java:728)
at
org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore.recoverNextMessages(KahaDBStore.java:485)
at
org.apache.activemq.store.ProxyMessageStore.recoverNextMessages(ProxyMessageStore.java:88)
at
org.apache.activemq.broker.region.cursors.QueueStorePrefetch.doFillBatch(QueueStorePrefetch.java:97)
at
org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:260)
... 7 more
2011-08-23 19:45:41,940 | ERROR | Failed to page in more queue messages |
org.apache.activemq.broker.region.Queue | Queue:TestQueue
java.lang.RuntimeException: java.lang.RuntimeException: java.io.IOException:
Could not locate data file C:\ActiveMQ\data\kahadb\db-11856.log
at
org.apache.activemq.broker.region.cursors.AbstractStoreCursor.reset(AbstractStoreCursor.java:111)
at
org.apache.activemq.broker.region.cursors.StoreQueueCursor.reset(StoreQueueCursor.java:157)
at
org.apache.activemq.broker.region.Queue.doPageInForDispatch(Queue.java:1712)
at
org.apache.activemq.broker.region.Queue.pageInMessages(Queue.java:1932)
at org.apache.activemq.broker.region.Queue.iterate(Queue.java:1440)
at
org.apache.activemq.thread.DedicatedTaskRunner.runTask(DedicatedTaskRunner.java:104)
at
org.apache.activemq.thread.DedicatedTaskRunner$1.run(DedicatedTaskRunner.java:42)
Caused by: java.lang.RuntimeException: java.io.IOException: Could not locate
data file C:\ActiveMQ\data\kahadb\db-11856.log
at
org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:263)
at
org.apache.activemq.broker.region.cursors.AbstractStoreCursor.reset(AbstractStoreCursor.java:108)
... 6 more
Caused by: java.io.IOException: Could not locate data file
C:\ActiveMQ\data\kahadb\db-11856.log
at org.apache.kahadb.journal.Journal.getDataFile(Journal.java:350)
at org.apache.kahadb.journal.Journal.read(Journal.java:597)
at
org.apache.activemq.store.kahadb.MessageDatabase.load(MessageDatabase.java:817)
at
org.apache.activemq.store.kahadb.KahaDBStore.loadMessage(KahaDBStore.java:955)
at
org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore$5.execute(KahaDBStore.java:493)
at org.apache.kahadb.page.Transaction.execute(Transaction.java:728)
at
org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore.recoverNextMessages(KahaDBStore.java:485)
at
org.apache.activemq.store.ProxyMessageStore.recoverNextMessages(ProxyMessageStore.java:88)
at
org.apache.activemq.broker.region.cursors.QueueStorePrefetch.doFillBatch(QueueStorePrefetch.java:97)
at
org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:260)
... 7 more
2011-08-23 19:45:41,942 | ERROR | Looking for key 11856 but not found in
fileMap: {11857=db-11857.log number = 11857 , length = 19540} |
org.apache.kahadb.journal.Journal | Queue:TestQueue
2011-08-23 19:45:41,943 | ERROR | QueueStorePrefetch314000409 - Failed to fill
batch | org.apache.activemq.broker.region.cursors.AbstractStoreCursor |
Queue:TestQueue
java.io.IOException: Could not locate data file
C:\ActiveMQ\data\kahadb\db-11856.log
at org.apache.kahadb.journal.Journal.getDataFile(Journal.java:350)
at org.apache.kahadb.journal.Journal.read(Journal.java:597)
at
org.apache.activemq.store.kahadb.MessageDatabase.load(MessageDatabase.java:817)
at
org.apache.activemq.store.kahadb.KahaDBStore.loadMessage(KahaDBStore.java:955)
at
org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore$5.execute(KahaDBStore.java:493)
at org.apache.kahadb.page.Transaction.execute(Transaction.java:728)
at
org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore.recoverNextMessages(KahaDBStore.java:485)
at
org.apache.activemq.store.ProxyMessageStore.recoverNextMessages(ProxyMessageStore.java:88)
at
org.apache.activemq.broker.region.cursors.QueueStorePrefetch.doFillBatch(QueueStorePrefetch.java:97)
at
org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:260)
at
org.apache.activemq.broker.region.cursors.AbstractStoreCursor.reset(AbstractStoreCursor.java:108)
at
org.apache.activemq.broker.region.cursors.StoreQueueCursor.reset(StoreQueueCursor.java:157)
at
org.apache.activemq.broker.region.Queue.doPageInForDispatch(Queue.java:1712)
at
org.apache.activemq.broker.region.Queue.pageInMessages(Queue.java:1932)
at org.apache.activemq.broker.region.Queue.iterate(Queue.java:1440)
at
org.apache.activemq.thread.DedicatedTaskRunner.runTask(DedicatedTaskRunner.java:104)
at
org.apache.activemq.thread.DedicatedTaskRunner$1.run(DedicatedTaskRunner.java:42)
2011-08-23 19:45:41,944 | ERROR | QueueStorePrefetch314000409 - Failed to fill
batch | org.apache.activemq.broker.region.cursors.AbstractStoreCursor |
Queue:TestQueue
java.lang.RuntimeException: java.io.IOException: Could not locate data file
C:\ActiveMQ\data\kahadb\db-11856.log
at
org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:263)
at
org.apache.activemq.broker.region.cursors.AbstractStoreCursor.reset(AbstractStoreCursor.java:108)
at
org.apache.activemq.broker.region.cursors.StoreQueueCursor.reset(StoreQueueCursor.java:157)
at
org.apache.activemq.broker.region.Queue.doPageInForDispatch(Queue.java:1712)
at
org.apache.activemq.broker.region.Queue.pageInMessages(Queue.java:1932)
at org.apache.activemq.broker.region.Queue.iterate(Queue.java:1440)
at
org.apache.activemq.thread.DedicatedTaskRunner.runTask(DedicatedTaskRunner.java:104)
at
org.apache.activemq.thread.DedicatedTaskRunner$1.run(DedicatedTaskRunner.java:42)
Caused by: java.io.IOException: Could not locate data file
C:\ActiveMQ\data\kahadb\db-11856.log
at org.apache.kahadb.journal.Journal.getDataFile(Journal.java:350)
at org.apache.kahadb.journal.Journal.read(Journal.java:597)
at
org.apache.activemq.store.kahadb.MessageDatabase.load(MessageDatabase.java:817)
at
org.apache.activemq.store.kahadb.KahaDBStore.loadMessage(KahaDBStore.java:955)
at
org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore$5.execute(KahaDBStore.java:493)
at org.apache.kahadb.page.Transaction.execute(Transaction.java:728)
at
org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore.recoverNextMessages(KahaDBStore.java:485)
at
org.apache.activemq.store.ProxyMessageStore.recoverNextMessages(ProxyMessageStore.java:88)
at
org.apache.activemq.broker.region.cursors.QueueStorePrefetch.doFillBatch(QueueStorePrefetch.java:97)
at
org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:260)
... 7 more
2011-08-23 19:45:41,945 | ERROR | Failed to page in more queue messages |
org.apache.activemq.broker.region.Queue | Queue:TestQueue
java.lang.RuntimeException: java.lang.RuntimeException: java.io.IOException:
Could not locate data file C:\ActiveMQ\data\kahadb\db-11856.log
at
org.apache.activemq.broker.region.cursors.AbstractStoreCursor.reset(AbstractStoreCursor.java:111)
at
org.apache.activemq.broker.region.cursors.StoreQueueCursor.reset(StoreQueueCursor.java:157)
at
org.apache.activemq.broker.region.Queue.doPageInForDispatch(Queue.java:1712)
at
org.apache.activemq.broker.region.Queue.pageInMessages(Queue.java:1932)
at org.apache.activemq.broker.region.Queue.iterate(Queue.java:1440)
at
org.apache.activemq.thread.DedicatedTaskRunner.runTask(DedicatedTaskRunner.java:104)
at
org.apache.activemq.thread.DedicatedTaskRunner$1.run(DedicatedTaskRunner.java:42)
Caused by: java.lang.RuntimeException: java.io.IOException: Could not locate
data file C:\ActiveMQ\data\kahadb\db-11856.log
at
org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:263)
at org.apa
---
The logs repeat in an endless matter.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
