Broker stuck showing error messages in log

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
3 messages Options
Reply | Threaded
Open this post in threaded view
|

Broker stuck showing error messages in log

pollotek
I restarted my stand alone persistent broker using KahaDB and I found this error message bellow in the log, no more messages are being consumed or forwarded. Advice? This is very high priority for me and quick help would be really appreciated.


INFO   | jvm 1    | 2012/09/18 23:13:50 | ERROR | Problem retrieving message for browse
INFO   | jvm 1    | 2012/09/18 23:13:50 | java.lang.RuntimeException: java.lang.RuntimeException: org.apache.activemq.protobuf.InvalidProtocolBufferException: Protocol message contained an invalid tag (zero).
INFO   | jvm 1    | 2012/09/18 23:13:50 | at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.reset(AbstractStoreCursor.java:116)
INFO   | jvm 1    | 2012/09/18 23:13:50 | at org.apache.activemq.broker.region.cursors.StoreQueueCursor.reset(StoreQueueCursor.java:157)
INFO   | jvm 1    | 2012/09/18 23:13:50 | at org.apache.activemq.broker.region.Queue.doBrowse(Queue.java:1069)
INFO   | jvm 1    | 2012/09/18 23:13:50 | at org.apache.activemq.broker.region.Queue.expireMessages(Queue.java:822)
INFO   | jvm 1    | 2012/09/18 23:13:50 | at org.apache.activemq.broker.region.Queue.access$100(Queue.java:96)
INFO   | jvm 1    | 2012/09/18 23:13:50 | at org.apache.activemq.broker.region.Queue$2.run(Queue.java:136)
INFO   | jvm 1    | 2012/09/18 23:13:50 | at org.apache.activemq.thread.SchedulerTimerTask.run(SchedulerTimerTask.java:33)
INFO   | jvm 1    | 2012/09/18 23:13:50 | at java.util.TimerThread.mainLoop(Timer.java:534)
INFO   | jvm 1    | 2012/09/18 23:13:50 | at java.util.TimerThread.run(Timer.java:484)
INFO   | jvm 1    | 2012/09/18 23:13:50 | Caused by: java.lang.RuntimeException: org.apache.activemq.protobuf.InvalidProtocolBufferException: Protocol message contained an invalid tag (zero).
INFO   | jvm 1    | 2012/09/18 23:13:50 | at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:280)
INFO   | jvm 1    | 2012/09/18 23:13:50 | at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.reset(AbstractStoreCursor.java:113)
INFO   | jvm 1    | 2012/09/18 23:13:50 | ... 8 more
INFO   | jvm 1    | 2012/09/18 23:13:50 | Caused by: org.apache.activemq.protobuf.InvalidProtocolBufferException: Protocol message contained an invalid tag (zero).
INFO   | jvm 1    | 2012/09/18 23:13:50 | at org.apache.activemq.protobuf.InvalidProtocolBufferException.invalidTag(InvalidProtocolBufferException.java:48)
INFO   | jvm 1    | 2012/09/18 23:13:50 | at org.apache.activemq.protobuf.CodedInputStream.readTag(CodedInputStream.java:75)
INFO   | jvm 1    | 2012/09/18 23:13:50 | at org.apache.activemq.store.kahadb.data.KahaAddMessageCommand.mergeUnframed(KahaAddMessageCommand.java:110)
INFO   | jvm 1    | 2012/09/18 23:13:50 | at org.apache.activemq.store.kahadb.data.KahaAddMessageCommand.mergeUnframed(KahaAddMessageCommand.java:7)
INFO   | jvm 1    | 2012/09/18 23:13:50 | at org.apache.activemq.protobuf.BaseMessage.mergeUnframed(BaseMessage.java:184)
INFO   | jvm 1    | 2012/09/18 23:13:50 | at org.apache.activemq.protobuf.BaseMessage.mergeUnframed(BaseMessage.java:213)
INFO   | jvm 1    | 2012/09/18 23:13:50 | at org.apache.activemq.protobuf.BaseMessage.mergeFramed(BaseMessage.java:237)
INFO   | jvm 1    | 2012/09/18 23:13:50 | at org.apache.activemq.store.kahadb.MessageDatabase.load(MessageDatabase.java:938)
INFO   | jvm 1    | 2012/09/18 23:13:50 | at org.apache.activemq.store.kahadb.KahaDBStore.loadMessage(KahaDBStore.java:1015)
INFO   | jvm 1    | 2012/09/18 23:13:50 | at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore$4.execute(KahaDBStore.java:556)
INFO   | jvm 1    | 2012/09/18 23:13:50 | at org.apache.kahadb.page.Transaction.execute(Transaction.java:769)
INFO   | jvm 1    | 2012/09/18 23:13:50 | at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore.recoverNextMessages(KahaDBStore.java:545)
INFO   | jvm 1    | 2012/09/18 23:13:50 | at org.apache.activemq.store.ProxyMessageStore.recoverNextMessages(ProxyMessageStore.java:106)
INFO   | jvm 1    | 2012/09/18 23:13:50 | at org.apache.activemq.broker.region.cursors.QueueStorePrefetch.doFillBatch(QueueStorePrefetch.java:97)
INFO   | jvm 1    | 2012/09/18 23:13:50 | at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:277)
INFO   | jvm 1    | 2012/09/18 23:13:50 | ... 9 more


The only config I have for KahaDB in my activemq.xml is the following:

        <persistenceAdapter>
            <kahaDB directory="/var/gluster/activemq/data/kahadb"/>
        </persistenceAdapter>


Thanks in advance.
Reply | Threaded
Open this post in threaded view
|

Re: Broker stuck showing error messages in log

pollotek
This post was updated on .
Based on some other post I decided to add the following parameters to my configuration:

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

The system seem to have started correctly but after a few minutes util it started throwing the following exceptions:

INFO   | jvm 1    | 2012/09/19 00:43:12 |  INFO | Recovering from the journal ...
INFO   | jvm 1    | 2012/09/19 00:43:12 |  INFO | Recovery replayed 1 operations from the journal in 0.017 seconds.
INFO   | jvm 1    | 2012/09/19 00:43:12 |  INFO | ActiveMQ 5.6.0 JMS Message Broker (broker) is starting
INFO   | jvm 1    | 2012/09/19 00:43:12 |  INFO | For help or more information please see: http://activemq.apache.org/
INFO   | jvm 1    | 2012/09/19 00:43:16 |  INFO | Listening for connections at: tcp://mqbroker02.xxxx.com:61616
INFO   | jvm 1    | 2012/09/19 00:43:16 |  INFO | Connector openwire Started
INFO   | jvm 1    | 2012/09/19 00:43:16 |  INFO | ActiveMQ JMS Message Broker (broker, ID:mqbroker02-57219-1348015392398-0:1) started
INFO   | jvm 1    | 2012/09/19 00:43:21 |  WARN | Duplicate message add attempt rejected. Destination: com.xxxx.queue.notification, Message id: ID:xxxxxx-56277-1348008881548-5:2:5273:1:1
INFO   | jvm 1    | 2012/09/19 00:43:26 |  WARN | Duplicate message add attempt rejected. Destination: com.xxxx.queue.timedData, Message id: ID:xxxxxx-451
37-1348003510612-5:2:1381:1:1
INFO   | jvm 1    | 2012/09/19 00:43:31 |  WARN | Duplicate message add attempt rejected. Destination: com.xxxx.queue.timedData, Message id: ID:app11-46276-1348004
200281-5:2:3293:1:1
INFO   | jvm 1    | 2012/09/19 00:43:32 |  WARN | Duplicate message add attempt rejected. Destination: com.xxxx.queue.notification, Message id: ID:app10.xxxx.com-49543-1348009973081-5:2:8111:1:1
INFO   | jvm 1    | 2012/09/19 00:43:33 |  WARN | Duplicate message add attempt rejected. Destination: com.xxxx.queue.timedData, Message id: ID:app12-47368-1348010
402189-5:2:6151:1:1
INFO   | jvm 1    | 2012/09/19 00:43:35 |  WARN | Duplicate message add attempt rejected. Destination: com.xxxx.queue.notification, Message id: ID:app3.xxxx.com-33478-1348008694249-5:2:5384:1:1
INFO   | jvm 1    | 2012/09/19 00:46:53 | ERROR | org.apache.activemq.broker.region.cursors.QueueStorePrefetch@2f012501:com.xxxx.queue.timedData,batchResetNeeded=f
alse,storeHasMessages=true,size=4,cacheEnabled=false - Failed to fill batch
INFO   | jvm 1    | 2012/09/19 00:46:53 | 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/19 00:46:53 |       at org.apache.activemq.store.kahadb.KahaDBStore.loadMessage(KahaDBStore.java:1015)
INFO   | jvm 1    | 2012/09/19 00:46:53 |       at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore$4.execute(KahaDBStore.java:556)
INFO   | jvm 1    | 2012/09/19 00:46:53 |       at org.apache.kahadb.page.Transaction.execute(Transaction.java:769)
INFO   | jvm 1    | 2012/09/19 00:46:53 |       at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore.recoverNextMessages(KahaDBStore.java:545)
INFO   | jvm 1    | 2012/09/19 00:46:53 |       at org.apache.activemq.store.ProxyMessageStore.recoverNextMessages(ProxyMessageStore.java:106)
INFO   | jvm 1    | 2012/09/19 00:46:53 |       at org.apache.activemq.broker.region.cursors.QueueStorePrefetch.doFillBatch(QueueStorePrefetch.java:97)
INFO   | jvm 1    | 2012/09/19 00:46:53 |       at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:277)
INFO   | jvm 1    | 2012/09/19 00:46:53 |       at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.reset(AbstractStoreCursor.java:113)
INFO   | jvm 1    | 2012/09/19 00:46:53 |       at org.apache.activemq.broker.region.cursors.StoreQueueCursor.reset(StoreQueueCursor.java:157)
INFO   | jvm 1    | 2012/09/19 00:46:53 |       at org.apache.activemq.broker.region.Queue.doPageInForDispatch(Queue.java:1766)
INFO   | jvm 1    | 2012/09/19 00:46:53 |       at org.apache.activemq.broker.region.Queue.pageInMessages(Queue.java:1995)
INFO   | jvm 1    | 2012/09/19 00:46:53 |       at org.apache.activemq.broker.region.Queue.iterate(Queue.java:1488)
INFO   | jvm 1    | 2012/09/19 00:46:53 |       at org.apache.activemq.thread.DedicatedTaskRunner.runTask(DedicatedTaskRunner.java:98)
INFO   | jvm 1    | 2012/09/19 00:46:53 |       at org.apache.activemq.thread.DedicatedTaskRunner$1.run(DedicatedTaskRunner.java:36)
INFO   | jvm 1    | 2012/09/19 00:46:53 | ERROR | org.apache.activemq.broker.region.cursors.QueueStorePrefetch@2f012501:com.xxxx.queue.timedData,batchResetNeeded=f
alse,storeHasMessages=true,size=4,cacheEnabled=false - Failed to fill batch
INFO   | jvm 1    | 2012/09/19 00:46:53 | 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/19 00:46:53 |       at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:280)
INFO   | jvm 1    | 2012/09/19 00:46:53 |       at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.reset(AbstractStoreCursor.java:113)
INFO   | jvm 1    | 2012/09/19 00:46:53 |       at org.apache.activemq.broker.region.cursors.StoreQueueCursor.reset(StoreQueueCursor.java:157)
INFO   | jvm 1    | 2012/09/19 00:46:53 |       at org.apache.activemq.broker.region.Queue.doPageInForDispatch(Queue.java:1766)
INFO   | jvm 1    | 2012/09/19 00:46:53 |       at org.apache.activemq.broker.region.Queue.pageInMessages(Queue.java:1995)
INFO   | jvm 1    | 2012/09/19 00:46:53 |       at org.apache.activemq.broker.region.Queue.iterate(Queue.java:1488)
INFO   | jvm 1    | 2012/09/19 00:46:53 |       at org.apache.activemq.thread.DedicatedTaskRunner.runTask(DedicatedTaskRunner.java:98)
INFO   | jvm 1    | 2012/09/19 00:46:53 |       at org.apache.activemq.thread.DedicatedTaskRunner$1.run(DedicatedTaskRunner.java:36)
INFO   | jvm 1    | 2012/09/19 00:46:53 | Caused by: java.lang.ClassCastException: org.apache.activemq.store.kahadb.data.KahaTraceCommand cannot be cast to org.apach
e.activemq.store.kahadb.data.KahaAddMessageCommand
INFO   | jvm 1    | 2012/09/19 00:46:53 |       at org.apache.activemq.store.kahadb.KahaDBStore.loadMessage(KahaDBStore.java:1015)
INFO   | jvm 1    | 2012/09/19 00:46:53 |       at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore$4.execute(KahaDBStore.java:556)
INFO   | jvm 1    | 2012/09/19 00:46:53 |       at org.apache.kahadb.page.Transaction.execute(Transaction.java:769)
INFO   | jvm 1    | 2012/09/19 00:46:53 |       at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore.recoverNextMessages(KahaDBStore.java:545)
INFO   | jvm 1    | 2012/09/19 00:46:53 |       at org.apache.activemq.store.ProxyMessageStore.recoverNextMessages(ProxyMessageStore.java:106)
INFO   | jvm 1    | 2012/09/19 00:46:53 |       at org.apache.activemq.broker.region.cursors.QueueStorePrefetch.doFillBatch(QueueStorePrefetch.java:97)
INFO   | jvm 1    | 2012/09/19 00:46:53 |       at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:277)
INFO   | jvm 1    | 2012/09/19 00:46:53 |       ... 7 more
INFO   | jvm 1    | 2012/09/19 00:46:53 | ERROR | Failed to page in more queue messages
INFO   | jvm 1    | 2012/09/19 00:46:53 | 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/19 00:46:53 |       at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.reset(AbstractStoreCursor.java:116)
INFO   | jvm 1    | 2012/09/19 00:46:53 |       at org.apache.activemq.broker.region.cursors.StoreQueueCursor.reset(StoreQueueCursor.java:157)
INFO   | jvm 1    | 2012/09/19 00:46:53 |       at org.apache.activemq.broker.region.Queue.doPageInForDispatch(Queue.java:1766)
INFO   | jvm 1    | 2012/09/19 00:46:53 |       at org.apache.activemq.broker.region.Queue.pageInMessages(Queue.java:1995)
INFO   | jvm 1    | 2012/09/19 00:46:53 |       at org.apache.activemq.broker.region.Queue.iterate(Queue.java:1488)
INFO   | jvm 1    | 2012/09/19 00:46:53 |       at org.apache.activemq.thread.DedicatedTaskRunner.runTask(DedicatedTaskRunner.java:98)
INFO   | jvm 1    | 2012/09/19 00:46:53 |       at org.apache.activemq.thread.DedicatedTaskRunner$1.run(DedicatedTaskRunner.java:36)
INFO   | jvm 1    | 2012/09/19 00:46:53 | 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/19 00:46:53 |       at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:280)
INFO   | jvm 1    | 2012/09/19 00:46:53 |       at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.reset(AbstractStoreCursor.java:113)
INFO   | jvm 1    | 2012/09/19 00:46:53 |       ... 6 more
INFO   | jvm 1    | 2012/09/19 00:46:53 | 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/19 00:46:53 |       at org.apache.activemq.store.kahadb.KahaDBStore.loadMessage(KahaDBStore.java:1015)
INFO   | jvm 1    | 2012/09/19 00:46:53 |       at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore$4.execute(KahaDBStore.java:556)
INFO   | jvm 1    | 2012/09/19 00:46:53 |       at org.apache.kahadb.page.Transaction.execute(Transaction.java:769)
INFO   | jvm 1    | 2012/09/19 00:46:53 |       at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore.recoverNextMessages(KahaDBStore.java:545)
INFO   | jvm 1    | 2012/09/19 00:46:53 |       at org.apache.activemq.store.ProxyMessageStore.recoverNextMessages(ProxyMessageStore.java:106)
INFO   | jvm 1    | 2012/09/19 00:46:53 |       at org.apache.activemq.broker.region.cursors.QueueStorePrefetch.doFillBatch(QueueStorePrefetch.java:97)
INFO   | jvm 1    | 2012/09/19 00:46:53 |       at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:277)
INFO   | jvm 1    | 2012/09/19 00:46:53 |       ... 7 more

This persistent stand alone broker has messages coming form embedded brokers and directly connected consumers. The message producing embedded brokers are still flowing to the stand alone broker, I can see the size of the queue grow but the consumers (I have 20 threads) are not getting any messages nor  throwing any exceptions.

Some help would be really appreciated.
Reply | Threaded
Open this post in threaded view
|

Re: Broker stuck showing error messages in log

pollotek
I was using GlusterFS to keep my master/slave shared file system in sync. When embedded broker clients disconnected from the stand alone broker somehow the indexes were getting corrupted and maybe some data files too.

I tried the same test several times without Gluster keeping a single master broker, no slave (because GlusterFS was my distributed FS mechanism) and never saw these issues again.

I blame GluterFS for these issues, probably there's some tuning to be done but personally I had a bad experience with it and would avoid it for medium load.