I tried this morning to replicate the issue on these two servers and was not able to do so. The only issue that I got was a few messages that got stuck in the queue with a consumer holding them hostage. either restarting that consumer or moving them to a different queue and back resolved that.
I did look at older errors that I had and found there recovery mode errors: INFO | jvm 1 | 2013/05/19 12:15:22 | INFO | DB recovered from failure. INFO | jvm 1 | 2013/05/19 12:15:22 | WARN | DB operation failed. (entering recovery mode) INFO | jvm 1 | 2013/05/19 12:15:22 | java.io.IOException: short record at position: 2467052 in file: /opt/activemq/data/0000000000000000.log, offset: 2467052 INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.leveldb.RecordLog$LogReader.read(RecordLog.scala:287) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.leveldb.RecordLog$$anonfun$read$2.apply(RecordLog.scala:543) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.leveldb.RecordLog$$anonfun$read$2.apply(RecordLog.scala:543) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.leveldb.RecordLog$$anonfun$get_reader$1.apply(RecordLog.scala:532) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.leveldb.RecordLog$$anonfun$get_reader$1.apply(RecordLog.scala:514) INFO | jvm 1 | 2013/05/19 12:15:22 | at scala.Option.map(Option.scala:133) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.leveldb.RecordLog.get_reader(RecordLog.scala:514) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.leveldb.RecordLog.read(RecordLog.scala:543) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.leveldb.LevelDBClient.getMessage(LevelDBClient.scala:1148) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.leveldb.LevelDBClient$$anonfun$queueCursor$1.apply(LevelDBClient.scala:1098) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.leveldb.LevelDBClient$$anonfun$queueCursor$1.apply(LevelDBClient.scala:1095) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.leveldb.LevelDBClient$$anonfun$collectionCursor$1$$anonfun$apply$mcV$sp$11.apply(LevelDBClient.scala:1171) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.leveldb.LevelDBClient$$anonfun$collectionCursor$1$$anonfun$apply$mcV$sp$11.apply(LevelDBClient.scala:1170) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.leveldb.LevelDBClient$RichDB.check$4(LevelDBClient.scala:311) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.leveldb.LevelDBClient$RichDB.cursorRange(LevelDBClient.scala:313) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.leveldb.LevelDBClient$$anonfun$collectionCursor$1.apply$mcV$sp(LevelDBClient.scala:1170) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.leveldb.LevelDBClient$$anonfun$collectionCursor$1.apply(LevelDBClient.scala:1170) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.leveldb.LevelDBClient$$anonfun$collectionCursor$1.apply(LevelDBClient.scala:1170) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.leveldb.LevelDBClient.usingIndex(LevelDBClient.scala:896) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.leveldb.LevelDBClient$$anonfun$retryUsingIndex$1.apply(LevelDBClient.scala:902) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.leveldb.util.RetrySupport$.retry(RetrySupport.scala:38) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.leveldb.LevelDBClient.retry(LevelDBClient.scala:504) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.leveldb.LevelDBClient.retryUsingIndex(LevelDBClient.scala:902) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.leveldb.LevelDBClient.collectionCursor(LevelDBClient.scala:1169) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.leveldb.LevelDBClient.queueCursor(LevelDBClient.scala:1095) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.leveldb.DBManager.cursorMessages(DBManager.scala:671) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.leveldb.LevelDBStore$LevelDBMessageStore.recoverNextMessages(LevelDBStore.scala:699) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.broker.region.cursors.QueueStorePrefetch.doFillBatch(QueueStorePrefetch.java:106) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:268) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.hasNext(AbstractStoreCursor.java:147) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.broker.region.cursors.StoreQueueCursor.hasNext(StoreQueueCursor.java:131) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.broker.region.Queue.doPageInForDispatch(Queue.java:1933) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.broker.region.Queue.pageInMessages(Queue.java:2160) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.broker.region.Queue.iterate(Queue.java:1634) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.broker.region.Queue.wakeup(Queue.java:1862) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.broker.region.Queue.addSubscription(Queue.java:497) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.broker.region.AbstractRegion.addConsumer(AbstractRegion.java:323) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.broker.region.RegionBroker.addConsumer(RegionBroker.java:390) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.broker.jmx.ManagedRegionBroker.addConsumer(ManagedRegionBroker.java:229) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.broker.BrokerFilter.addConsumer(BrokerFilter.java:97) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.advisory.AdvisoryBroker.addConsumer(AdvisoryBroker.java:76) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.broker.BrokerFilter.addConsumer(BrokerFilter.java:97) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.broker.BrokerFilter.addConsumer(BrokerFilter.java:97) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.broker.MutableBrokerFilter.addConsumer(MutableBrokerFilter.java:102) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.broker.TransportConnection.processAddConsumer(TransportConnection.java:619) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.command.ConsumerInfo.visit(ConsumerInfo.java:332) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:329) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:184) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:113) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.transport.AbstractInactivityMonitor.onCommand(AbstractInactivityMonitor.java:288) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:214) INFO | jvm 1 | 2013/05/19 12:15:22 | at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:196) INFO | jvm 1 | 2013/05/19 12:15:22 | at java.lang.Thread.run(Thread.java:722) INFO | jvm 1 | 2013/05/19 12:16:58 | INFO | DB recovered from failure. INFO | jvm 1 | 2013/05/19 12:16:58 | WARN | DB operation failed. (entering recovery mode) INFO | jvm 1 | 2013/05/19 12:16:58 | java.io.IOException: short record at position: 2467052 in file: /opt/activemq/data/0000000000000000.log, offset: 2467052 INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.leveldb.RecordLog$LogReader.read(RecordLog.scala:287) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.leveldb.RecordLog$$anonfun$read$2.apply(RecordLog.scala:543) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.leveldb.RecordLog$$anonfun$read$2.apply(RecordLog.scala:543) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.leveldb.RecordLog$$anonfun$get_reader$1.apply(RecordLog.scala:532) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.leveldb.RecordLog$$anonfun$get_reader$1.apply(RecordLog.scala:514) INFO | jvm 1 | 2013/05/19 12:16:58 | at scala.Option.map(Option.scala:133) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.leveldb.RecordLog.get_reader(RecordLog.scala:514) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.leveldb.RecordLog.read(RecordLog.scala:543) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.leveldb.LevelDBClient.getMessage(LevelDBClient.scala:1148) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.leveldb.LevelDBClient$$anonfun$queueCursor$1.apply(LevelDBClient.scala:1098) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.leveldb.LevelDBClient$$anonfun$queueCursor$1.apply(LevelDBClient.scala:1095) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.leveldb.LevelDBClient$$anonfun$collectionCursor$1$$anonfun$apply$mcV$sp$11.apply(LevelDBClient.scala:1171) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.leveldb.LevelDBClient$$anonfun$collectionCursor$1$$anonfun$apply$mcV$sp$11.apply(LevelDBClient.scala:1170) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.leveldb.LevelDBClient$RichDB.check$4(LevelDBClient.scala:311) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.leveldb.LevelDBClient$RichDB.cursorRange(LevelDBClient.scala:313) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.leveldb.LevelDBClient$$anonfun$collectionCursor$1.apply$mcV$sp(LevelDBClient.scala:1170) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.leveldb.LevelDBClient$$anonfun$collectionCursor$1.apply(LevelDBClient.scala:1170) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.leveldb.LevelDBClient$$anonfun$collectionCursor$1.apply(LevelDBClient.scala:1170) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.leveldb.LevelDBClient.usingIndex(LevelDBClient.scala:896) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.leveldb.LevelDBClient$$anonfun$retryUsingIndex$1.apply(LevelDBClient.scala:902) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.leveldb.util.RetrySupport$.retry(RetrySupport.scala:38) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.leveldb.LevelDBClient.retry(LevelDBClient.scala:504) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.leveldb.LevelDBClient.retryUsingIndex(LevelDBClient.scala:902) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.leveldb.LevelDBClient.collectionCursor(LevelDBClient.scala:1169) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.leveldb.LevelDBClient.queueCursor(LevelDBClient.scala:1095) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.leveldb.DBManager.cursorMessages(DBManager.scala:671) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.leveldb.LevelDBStore$LevelDBMessageStore.recoverNextMessages(LevelDBStore.scala:699) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.broker.region.cursors.QueueStorePrefetch.doFillBatch(QueueStorePrefetch.java:106) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:268) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.hasNext(AbstractStoreCursor.java:147) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.broker.region.cursors.StoreQueueCursor.hasNext(StoreQueueCursor.java:131) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.broker.region.Queue.doPageInForDispatch(Queue.java:1933) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.broker.region.Queue.pageInMessages(Queue.java:2160) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.broker.region.Queue.iterate(Queue.java:1634) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.broker.region.Queue.wakeup(Queue.java:1862) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.broker.region.Queue.addSubscription(Queue.java:497) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.broker.region.AbstractRegion.addConsumer(AbstractRegion.java:323) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.broker.region.RegionBroker.addConsumer(RegionBroker.java:390) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.broker.jmx.ManagedRegionBroker.addConsumer(ManagedRegionBroker.java:229) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.broker.BrokerFilter.addConsumer(BrokerFilter.java:97) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.advisory.AdvisoryBroker.addConsumer(AdvisoryBroker.java:76) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.broker.BrokerFilter.addConsumer(BrokerFilter.java:97) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.broker.BrokerFilter.addConsumer(BrokerFilter.java:97) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.broker.MutableBrokerFilter.addConsumer(MutableBrokerFilter.java:102) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.broker.TransportConnection.processAddConsumer(TransportConnection.java:619) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.command.ConsumerInfo.visit(ConsumerInfo.java:332) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:329) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:184) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:113) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.transport.AbstractInactivityMonitor.onCommand(AbstractInactivityMonitor.java:288) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:214) INFO | jvm 1 | 2013/05/19 12:16:58 | at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:196) INFO | jvm 1 | 2013/05/19 12:16:58 | at java.lang.Thread.run(Thread.java:722) -freddy On May 30, 2013, at 2:05 PM, chirino [via ActiveMQ] wrote: > If you got a 'DB recovered from failure.' message, then it should have > been preceded with an 'DB operation failed. (entering recovery mode)' > message. Could you post that message? > > On Tue, May 28, 2013 at 1:47 PM, heimdull <[hidden email]> wrote: > > > I started testing this on a setup where I manually generate messages and > > I'm > > not able replicate the issue. I think it only happens if there is moderate > > load when failing over. > > > > Here is the exact message that shows in the setup where I can replicate the > > issue: > > > > 2013-05-28 10:42:56,977 | INFO | DB recovered from failure. | > > org.apache.activemq.leveldb.LevelDBClient | ActiveMQ NIO Worker 93 > > > > This message shows up in my log after a failover when I delete the broken > > queue. After that message I have these: > > > > 2013-05-28 10:42:56,990 | WARN | Async error occurred: > > java.lang.IllegalArgumentException: The subscription does not exist: > > ID:xx03-35870-1369757354540-1:3:5:1 | > > org.apache.activemq.broker.TransportConnection.Service | ActiveMQ NIO > > Worker > > 29 > > java.lang.IllegalArgumentException: The subscription does not exist: > > ID:xx03-35870-1369757354540-1:3:5:1 > > at > > org.apache.activemq.broker.region.AbstractRegion.messagePull(AbstractRegion.java:432) > > > > at > > org.apache.activemq.broker.region.RegionBroker.messagePull(RegionBroker.java:468) > > > > at > > org.apache.activemq.broker.BrokerFilter.messagePull(BrokerFilter.java:87) > > > > > > > > -- > > View this message in context: > > http://activemq.2283324.n4.nabble.com/Activemq-5-9-leveldb-replication-issue-tp4667495p4667560.html > > Sent from the ActiveMQ - User mailing list archive at Nabble.com. > > > > -- > Hiram Chirino > > Engineering | Red Hat, Inc. > > [hidden email] | fusesource.com | redhat.com > > skype: hiramchirino | twitter: @hiramchirino > > blog: Hiram Chirino's Bit Mojo > > > If you reply to this email, your message will be added to the discussion > below: > http://activemq.2283324.n4.nabble.com/Activemq-5-9-leveldb-replication-issue-tp4667495p4667674.html > To unsubscribe from Activemq 5.9 leveldb replication issue, click here. > NAML -- View this message in context: http://activemq.2283324.n4.nabble.com/Activemq-5-9-leveldb-replication-issue-tp4667495p4667709.html Sent from the ActiveMQ - User mailing list archive at Nabble.com.
