Return-Path: X-Original-To: apmail-activemq-users-archive@www.apache.org Delivered-To: apmail-activemq-users-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id 9165BF7C0 for ; Fri, 31 May 2013 17:30:22 +0000 (UTC) Received: (qmail 29246 invoked by uid 500); 31 May 2013 17:30:22 -0000 Delivered-To: apmail-activemq-users-archive@activemq.apache.org Received: (qmail 28838 invoked by uid 500); 31 May 2013 17:30:20 -0000 Mailing-List: contact users-help@activemq.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: users@activemq.apache.org Delivered-To: mailing list users@activemq.apache.org Received: (qmail 28809 invoked by uid 99); 31 May 2013 17:30:19 -0000 Received: from athena.apache.org (HELO athena.apache.org) (140.211.11.136) by apache.org (qpsmtpd/0.29) with ESMTP; Fri, 31 May 2013 17:30:19 +0000 X-ASF-Spam-Status: No, hits=3.5 required=5.0 tests=HTML_MESSAGE,URI_HEX X-Spam-Check-By: apache.org Received-SPF: error (athena.apache.org: local policy) Received: from [216.139.250.139] (HELO joe.nabble.com) (216.139.250.139) by apache.org (qpsmtpd/0.29) with ESMTP; Fri, 31 May 2013 17:30:15 +0000 Received: from [192.168.236.139] (helo=joe.nabble.com) by joe.nabble.com with esmtp (Exim 4.72) (envelope-from ) id 1UiT8W-0002Fe-Tz for users@activemq.apache.org; Fri, 31 May 2013 10:29:08 -0700 Date: Fri, 31 May 2013 10:28:53 -0700 (PDT) From: heimdull To: users@activemq.apache.org Message-ID: <3C05E861-4DEB-438C-976B-FCEB29824F33@cfandersen.com> In-Reply-To: References: <1369578103634-4667495.post@n4.nabble.com> <1369712834158-4667522.post@n4.nabble.com> <1369763262357-4667560.post@n4.nabble.com> Subject: Re: Activemq 5.9 leveldb replication issue MIME-Version: 1.0 Content-Type: multipart/alternative; boundary="----=_Part_29474_24719387.1370021333912" X-Virus-Checked: Checked by ClamAV on apache.org ------=_Part_29474_24719387.1370021333912 Content-Type: text/plain; charset=us-ascii Content-Transfer-Encoding: 7bit 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. ------=_Part_29474_24719387.1370021333912--