Uploaded image for project: 'ActiveMQ'
  1. ActiveMQ
  2. AMQ-3470

Unable to pick up messages anymore, messages are lost - Looking for key xyz but not found in fileMap

    XMLWordPrintableJSON

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Blocker
    • Resolution: Incomplete
    • Affects Version/s: 5.5.0
    • Fix Version/s: None
    • Component/s: None
    • Labels:
      None
    • 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

      Description

      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 SelectChannelConnector@0.0.0.0: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.

        Attachments

          Issue Links

            Activity

              People

              • Assignee:
                Unassigned
                Reporter:
                fgynnild Frank Gynnild
              • Votes:
                0 Vote for this issue
                Watchers:
                2 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: