ActiveMQ
  1. ActiveMQ
  2. AMQ-4071

Restarting of persistent embedded broker causing Failed to fill batch error

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Critical Critical
    • Resolution: Won't Fix
    • Affects Version/s: 5.6.0
    • Fix Version/s: None
    • Component/s: Broker
    • Labels:
      None
    • Environment:

      Ubuntu 12.04.1 LTS

      java version "1.6.0_32"
      Java(TM) SE Runtime Environment (build 1.6.0_32-b05)
      Java HotSpot(TM) 64-Bit Server VM (build 20.7-b02, mixed mode)

      Tomcat 6.0.35

      Description

      I have a Tomcat web container with a persistent embedded broker in it, all messages get produced in this web container and queued up in the embedded broker. The embedded broker connects to a stand alone master/slave shared storage broker and finally the messages get consumed by threads clients connecting directly to the stand alone broker. The consumers run inside a Tomcat web container of the same version.

      While the stand alone broker is enqueueing about 17 messages a second I restart the message producers which have embedded brokers the exception bellow starts appearing in the stand alone broker log:

      INFO | jvm 1 | 2012/09/21 22:00:32 | ERROR | org.apache.activemq.broker.region.cursors.QueueStorePrefetch@40b1d29:myqueue,batchResetNeeded=false,storeHasMessages=true,size=30650,cacheEnabled=false - Failed to fill batch
      INFO | jvm 1 | 2012/09/21 22:00:32 | java.lang.RuntimeException: java.lang.ClassCastException: org.apache.activemq.store.kahadb.data.KahaTraceCommand cannot be cast to org.apache.activemq.store.kahadb.data.KahaAddMessageCommand
      INFO | jvm 1 | 2012/09/21 22:00:32 | at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:280)
      INFO | jvm 1 | 2012/09/21 22:00:32 | at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.reset(AbstractStoreCursor.java:113)
      INFO | jvm 1 | 2012/09/21 22:00:32 | at org.apache.activemq.broker.region.cursors.StoreQueueCursor.reset(StoreQueueCursor.java:157)
      INFO | jvm 1 | 2012/09/21 22:00:32 | at org.apache.activemq.broker.region.Queue.doPageInForDispatch(Queue.java:1766)
      INFO | jvm 1 | 2012/09/21 22:00:32 | at org.apache.activemq.broker.region.Queue.pageInMessages(Queue.java:1995)
      INFO | jvm 1 | 2012/09/21 22:00:32 | at org.apache.activemq.broker.region.Queue.iterate(Queue.java:1488)
      INFO | jvm 1 | 2012/09/21 22:00:32 | at org.apache.activemq.thread.DedicatedTaskRunner.runTask(DedicatedTaskRunner.java:98)
      INFO | jvm 1 | 2012/09/21 22:00:32 | at org.apache.activemq.thread.DedicatedTaskRunner$1.run(DedicatedTaskRunner.java:36)
      INFO | jvm 1 | 2012/09/21 22:00:32 | Caused by: java.lang.ClassCastException: org.apache.activemq.store.kahadb.data.KahaTraceCommand cannot be cast to org.apache.activemq.store.kahadb.data.KahaAddMessageCommand
      INFO | jvm 1 | 2012/09/21 22:00:32 | at org.apache.activemq.store.kahadb.KahaDBStore.loadMessage(KahaDBStore.java:1015)
      INFO | jvm 1 | 2012/09/21 22:00:32 | at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore$4.execute(KahaDBStore.java:556)
      INFO | jvm 1 | 2012/09/21 22:00:32 | at org.apache.kahadb.page.Transaction.execute(Transaction.java:769)
      INFO | jvm 1 | 2012/09/21 22:00:32 | at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore.recoverNextMessages(KahaDBStore.java:545)
      INFO | jvm 1 | 2012/09/21 22:00:32 | at org.apache.activemq.store.ProxyMessageStore.recoverNextMessages(ProxyMessageStore.java:106)
      INFO | jvm 1 | 2012/09/21 22:00:32 | at org.apache.activemq.broker.region.cursors.QueueStorePrefetch.doFillBatch(QueueStorePrefetch.java:97)
      INFO | jvm 1 | 2012/09/21 22:00:32 | at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:277)
      INFO | jvm 1 | 2012/09/21 22:00:32 | ... 7 more
      INFO | jvm 1 | 2012/09/21 22:00:32 | ERROR | Failed to page in more queue messages
      INFO | jvm 1 | 2012/09/21 22:00:32 | java.lang.RuntimeException: java.lang.RuntimeException: java.lang.ClassCastException: org.apache.activemq.store.kahadb.data.KahaTraceCommand cannot be cast to org.apache.activemq.store.kahadb.data.KahaAddMessageCommand
      INFO | jvm 1 | 2012/09/21 22:00:32 | at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.reset(AbstractStoreCursor.java:116)
      INFO | jvm 1 | 2012/09/21 22:00:32 | at org.apache.activemq.broker.region.cursors.StoreQueueCursor.reset(StoreQueueCursor.java:157)
      INFO | jvm 1 | 2012/09/21 22:00:32 | at org.apache.activemq.broker.region.Queue.doPageInForDispatch(Queue.java:1766)
      INFO | jvm 1 | 2012/09/21 22:00:32 | at org.apache.activemq.broker.region.Queue.pageInMessages(Queue.java:1995)
      INFO | jvm 1 | 2012/09/21 22:00:32 | at org.apache.activemq.broker.region.Queue.iterate(Queue.java:1488)
      INFO | jvm 1 | 2012/09/21 22:00:32 | at org.apache.activemq.thread.DedicatedTaskRunner.runTask(DedicatedTaskRunner.java:98)
      INFO | jvm 1 | 2012/09/21 22:00:32 | at org.apache.activemq.thread.DedicatedTaskRunner$1.run(DedicatedTaskRunner.java:36)
      INFO | jvm 1 | 2012/09/21 22:00:32 | Caused by: java.lang.RuntimeException: java.lang.ClassCastException: org.apache.activemq.store.kahadb.data.KahaTraceCommand cannot be cast to org.apache.activemq.store.kahadb.data.KahaAddMessageCommand
      INFO | jvm 1 | 2012/09/21 22:00:32 | at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:280)
      INFO | jvm 1 | 2012/09/21 22:00:32 | at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.reset(AbstractStoreCursor.java:113)
      INFO | jvm 1 | 2012/09/21 22:00:32 | ... 6 more
      INFO | jvm 1 | 2012/09/21 22:00:32 | Caused by: java.lang.ClassCastException: org.apache.activemq.store.kahadb.data.KahaTraceCommand cannot be cast to org.apache.activemq.store.kahadb.data.KahaAddMessageCommand
      INFO | jvm 1 | 2012/09/21 22:00:32 | at org.apache.activemq.store.kahadb.KahaDBStore.loadMessage(KahaDBStore.java:1015)
      INFO | jvm 1 | 2012/09/21 22:00:32 | at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore$4.execute(KahaDBStore.java:556)
      INFO | jvm 1 | 2012/09/21 22:00:32 | at org.apache.kahadb.page.Transaction.execute(Transaction.java:769)
      INFO | jvm 1 | 2012/09/21 22:00:32 | at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore.recoverNextMessages(KahaDBStore.java:545)
      INFO | jvm 1 | 2012/09/21 22:00:32 | at org.apache.activemq.store.ProxyMessageStore.recoverNextMessages(ProxyMessageStore.java:106)
      INFO | jvm 1 | 2012/09/21 22:00:32 | at org.apache.activemq.broker.region.cursors.QueueStorePrefetch.doFillBatch(QueueStorePrefetch.java:97)
      INFO | jvm 1 | 2012/09/21 22:00:32 | at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:277)
      INFO | jvm 1 | 2012/09/21 22:00:32 | ... 7 more

      I have 5 different queues in my brokers and I don't see any issues with any of the other queues. I've experienced this issue before and some other queue was the one affected.

      These servers were being used at about 5 messages per second, they would be regularly restarted and this issue never appeared before.

      My persistence adapter config

      <persistenceAdapter>
      <kahaDB directory="/var/gluster/activemq/data/kahadb"
      ignoreMissingJournalfiles="true"
      checkForCorruptJournalFiles="true"
      checksumJournalFiles="true"/>
      </persistenceAdapter>

        Activity

        Hide
        Claudio Santana added a comment -

        I tried to reproduce this manually without GlusterFS configured and was unable to do so.

        I would not recommend using GlusterFS with master/slave shared file system with more than probably 15 enqueued/dequeued messages per second.

        Show
        Claudio Santana added a comment - I tried to reproduce this manually without GlusterFS configured and was unable to do so. I would not recommend using GlusterFS with master/slave shared file system with more than probably 15 enqueued/dequeued messages per second.

          People

          • Assignee:
            Unassigned
            Reporter:
            Claudio Santana
          • Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development