activemq-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From heimdull <fre...@cfandersen.com>
Subject Re: Activemq 5.9 leveldb replication issue
Date Fri, 31 May 2013 17:28:53 GMT
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.
Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message