[
https://issues.apache.org/jira/browse/AMQ-3470?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13091707#comment-13091707
]
Gary Tully commented on AMQ-3470:
---------------------------------
to follow up on Dejan's comment, some detail on the MessageDatabase logging
that will help understand the cleanup process.
http://activemq.apache.org/why-do-kahadb-log-files-remain-after-cleanup.html
> 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
> Affects Versions: 5.5.0
> 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
