Return-Path: X-Original-To: apmail-activemq-dev-archive@www.apache.org Delivered-To: apmail-activemq-dev-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id EF30C10FFE for ; Tue, 4 Mar 2014 13:18:22 +0000 (UTC) Received: (qmail 97097 invoked by uid 500); 4 Mar 2014 13:18:21 -0000 Delivered-To: apmail-activemq-dev-archive@activemq.apache.org Received: (qmail 97037 invoked by uid 500); 4 Mar 2014 13:18:20 -0000 Mailing-List: contact dev-help@activemq.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@activemq.apache.org Delivered-To: mailing list dev@activemq.apache.org Received: (qmail 97025 invoked by uid 99); 4 Mar 2014 13:18:20 -0000 Received: from arcas.apache.org (HELO arcas.apache.org) (140.211.11.28) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 04 Mar 2014 13:18:20 +0000 Date: Tue, 4 Mar 2014 13:18:20 +0000 (UTC) From: =?utf-8?Q?H=C3=A5kan_Dahl_=28JIRA=29?= To: dev@activemq.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Updated] (AMQ-5081) LevelDB logging "WARN | Invalid log position" after restart MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 [ https://issues.apache.org/jira/browse/AMQ-5081?page=3Dcom.atlassian.= jira.plugin.system.issuetabpanels:all-tabpanel ] H=C3=A5kan Dahl updated AMQ-5081: ---------------------------- Description:=20 Seems related to APLO-284. Problem occurs occasionally after restart of broker when using LevelDB. The broker starts to log very intensively (doesn't seem to stop): --- --- jvm 1 | WARN | Invalid log position: 79672162 jvm 1 | WARN | Invalid log position: 79673204 jvm 1 | WARN | Invalid log position: 79674246 jvm 1 | WARN | Invalid log position: 79683816 jvm 1 | WARN | Invalid log position: 79686990 jvm 1 | WARN | Invalid log position: 79690164 --- After a second restart the logging has stopped but the broker is constantly= restarting itself due to a LevelDB problem (see attached logfile), had to = remove the leveldb-dir from disk to get the broker to run normally again (s= ee attached leveldb-store containing the problem): 2014-03-04 13:59:38,443 | INFO | Stopping BrokerService[localhost] due to = exception, java.io.IOException | org.apache.activemq.util.DefaultIOExceptio= nHandler | LevelDB IOException handler. java.io.IOException =09at org.apache.activemq.util.IOExceptionSupport.create(IOExceptionSupport= .java:39) =09at org.apache.activemq.leveldb.LevelDBClient.might_fail(LevelDBClient.sc= ala:543) =09at org.apache.activemq.leveldb.LevelDBClient.might_fail_using_index(Leve= lDBClient.scala:974) =09at org.apache.activemq.leveldb.LevelDBClient.collectionCursor(LevelDBCli= ent.scala:1270) =09at org.apache.activemq.leveldb.LevelDBClient.queueCursor(LevelDBClient.s= cala:1194) =09at org.apache.activemq.leveldb.DBManager.cursorMessages(DBManager.scala:= 708) =09at org.apache.activemq.leveldb.LevelDBStore$LevelDBMessageStore.recoverN= extMessages(LevelDBStore.scala:741) =09at org.apache.activemq.broker.region.cursors.QueueStorePrefetch.doFillBa= tch(QueueStorePrefetch.java:106) =09at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBat= ch(AbstractStoreCursor.java:258) =09at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.reset(A= bstractStoreCursor.java:108) =09at org.apache.activemq.broker.region.cursors.StoreQueueCursor.reset(Stor= eQueueCursor.java:157) =09at org.apache.activemq.broker.region.Queue.doPageInForDispatch(Queue.jav= a:1875) =09at org.apache.activemq.broker.region.Queue.pageInMessages(Queue.java:208= 6) =09at org.apache.activemq.broker.region.Queue.doBrowse(Queue.java:1096) =09at org.apache.activemq.broker.region.Queue.expireMessages(Queue.java:905= ) =09at org.apache.activemq.broker.region.Queue.access$100(Queue.java:79) =09at org.apache.activemq.broker.region.Queue$2.run(Queue.java:120) =09at org.apache.activemq.thread.SchedulerTimerTask.run(SchedulerTimerTask.= java:33) =09at java.util.TimerThread.mainLoop(Unknown Source) =09at java.util.TimerThread.run(Unknown Source) Caused by: java.lang.NullPointerException =09at org.apache.activemq.leveldb.LevelDBClient$$anonfun$queueCursor$1.appl= y(LevelDBClient.scala:1198) =09at org.apache.activemq.leveldb.LevelDBClient$$anonfun$queueCursor$1.appl= y(LevelDBClient.scala:1194) =09at org.apache.activemq.leveldb.LevelDBClient$$anonfun$collectionCursor$1= $$anonfun$apply$mcV$sp$12.apply(LevelDBClient.scala:1272) =09at org.apache.activemq.leveldb.LevelDBClient$$anonfun$collectionCursor$1= $$anonfun$apply$mcV$sp$12.apply(LevelDBClient.scala:1271) =09at org.apache.activemq.leveldb.LevelDBClient$RichDB.check$4(LevelDBClien= t.scala:315) was: Seems related to APLO-284. Problem occurs occasionally after restart of broker when using LevelDB. The broker starts to log very intensively (doesn't seem to stop): --- jvm 1 | WARN | Invalid log position: 79672162 jvm 1 | WARN | Invalid log position: 79673204 jvm 1 | WARN | Invalid log position: 79674246 jvm 1 | WARN | Invalid log position: 79683816 jvm 1 | WARN | Invalid log position: 79686990 jvm 1 | WARN | Invalid log position: 79690164 --- After a second restart the logging has stopped but the broker is constantly= restarting itself due to a LevelDB problem (see attached logfile), had to = remove the leveldb-dir from disk to get the broker to run normally again (s= ee attached leveldb-store containing the problem): 2014-03-04 13:59:38,443 | INFO | Stopping BrokerService[localhost] due to = exception, java.io.IOException | org.apache.activemq.util.DefaultIOExceptio= nHandler | LevelDB IOException handler. java.io.IOException =09at org.apache.activemq.util.IOExceptionSupport.create(IOExceptionSupport= .java:39) =09at org.apache.activemq.leveldb.LevelDBClient.might_fail(LevelDBClient.sc= ala:543) =09at org.apache.activemq.leveldb.LevelDBClient.might_fail_using_index(Leve= lDBClient.scala:974) =09at org.apache.activemq.leveldb.LevelDBClient.collectionCursor(LevelDBCli= ent.scala:1270) =09at org.apache.activemq.leveldb.LevelDBClient.queueCursor(LevelDBClient.s= cala:1194) =09at org.apache.activemq.leveldb.DBManager.cursorMessages(DBManager.scala:= 708) =09at org.apache.activemq.leveldb.LevelDBStore$LevelDBMessageStore.recoverN= extMessages(LevelDBStore.scala:741) =09at org.apache.activemq.broker.region.cursors.QueueStorePrefetch.doFillBa= tch(QueueStorePrefetch.java:106) =09at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBat= ch(AbstractStoreCursor.java:258) =09at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.reset(A= bstractStoreCursor.java:108) =09at org.apache.activemq.broker.region.cursors.StoreQueueCursor.reset(Stor= eQueueCursor.java:157) =09at org.apache.activemq.broker.region.Queue.doPageInForDispatch(Queue.jav= a:1875) =09at org.apache.activemq.broker.region.Queue.pageInMessages(Queue.java:208= 6) =09at org.apache.activemq.broker.region.Queue.doBrowse(Queue.java:1096) =09at org.apache.activemq.broker.region.Queue.expireMessages(Queue.java:905= ) =09at org.apache.activemq.broker.region.Queue.access$100(Queue.java:79) =09at org.apache.activemq.broker.region.Queue$2.run(Queue.java:120) =09at org.apache.activemq.thread.SchedulerTimerTask.run(SchedulerTimerTask.= java:33) =09at java.util.TimerThread.mainLoop(Unknown Source) =09at java.util.TimerThread.run(Unknown Source) Caused by: java.lang.NullPointerException =09at org.apache.activemq.leveldb.LevelDBClient$$anonfun$queueCursor$1.appl= y(LevelDBClient.scala:1198) =09at org.apache.activemq.leveldb.LevelDBClient$$anonfun$queueCursor$1.appl= y(LevelDBClient.scala:1194) =09at org.apache.activemq.leveldb.LevelDBClient$$anonfun$collectionCursor$1= $$anonfun$apply$mcV$sp$12.apply(LevelDBClient.scala:1272) =09at org.apache.activemq.leveldb.LevelDBClient$$anonfun$collectionCursor$1= $$anonfun$apply$mcV$sp$12.apply(LevelDBClient.scala:1271) =09at org.apache.activemq.leveldb.LevelDBClient$RichDB.check$4(LevelDBClien= t.scala:315) > LevelDB logging "WARN | Invalid log position" after restart > ----------------------------------------------------------- > > Key: AMQ-5081 > URL: https://issues.apache.org/jira/browse/AMQ-5081 > Project: ActiveMQ > Issue Type: Bug > Components: activemq-leveldb-store > Affects Versions: 5.9.0 > Environment: Win7/64bit > Reporter: H=C3=A5kan Dahl > Attachments: activemq.log, leveldb.zip, wrapper.log > > > Seems related to APLO-284. > Problem occurs occasionally after restart of broker when using LevelDB. > The broker starts to log very intensively (doesn't seem to stop): > --- > > > > --- > jvm 1 | WARN | Invalid log position: 79672162 > jvm 1 | WARN | Invalid log position: 79673204 > jvm 1 | WARN | Invalid log position: 79674246 > jvm 1 | WARN | Invalid log position: 79683816 > jvm 1 | WARN | Invalid log position: 79686990 > jvm 1 | WARN | Invalid log position: 79690164 > --- > After a second restart the logging has stopped but the broker is constant= ly restarting itself due to a LevelDB problem (see attached logfile), had t= o remove the leveldb-dir from disk to get the broker to run normally again = (see attached leveldb-store containing the problem): > 2014-03-04 13:59:38,443 | INFO | Stopping BrokerService[localhost] due t= o exception, java.io.IOException | org.apache.activemq.util.DefaultIOExcept= ionHandler | LevelDB IOException handler. > java.io.IOException > =09at org.apache.activemq.util.IOExceptionSupport.create(IOExceptionSuppo= rt.java:39) > =09at org.apache.activemq.leveldb.LevelDBClient.might_fail(LevelDBClient.= scala:543) > =09at org.apache.activemq.leveldb.LevelDBClient.might_fail_using_index(Le= velDBClient.scala:974) > =09at org.apache.activemq.leveldb.LevelDBClient.collectionCursor(LevelDBC= lient.scala:1270) > =09at org.apache.activemq.leveldb.LevelDBClient.queueCursor(LevelDBClient= .scala:1194) > =09at org.apache.activemq.leveldb.DBManager.cursorMessages(DBManager.scal= a:708) > =09at org.apache.activemq.leveldb.LevelDBStore$LevelDBMessageStore.recove= rNextMessages(LevelDBStore.scala:741) > =09at org.apache.activemq.broker.region.cursors.QueueStorePrefetch.doFill= Batch(QueueStorePrefetch.java:106) > =09at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillB= atch(AbstractStoreCursor.java:258) > =09at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.reset= (AbstractStoreCursor.java:108) > =09at org.apache.activemq.broker.region.cursors.StoreQueueCursor.reset(St= oreQueueCursor.java:157) > =09at org.apache.activemq.broker.region.Queue.doPageInForDispatch(Queue.j= ava:1875) > =09at org.apache.activemq.broker.region.Queue.pageInMessages(Queue.java:2= 086) > =09at org.apache.activemq.broker.region.Queue.doBrowse(Queue.java:1096) > =09at org.apache.activemq.broker.region.Queue.expireMessages(Queue.java:9= 05) > =09at org.apache.activemq.broker.region.Queue.access$100(Queue.java:79) > =09at org.apache.activemq.broker.region.Queue$2.run(Queue.java:120) > =09at org.apache.activemq.thread.SchedulerTimerTask.run(SchedulerTimerTas= k.java:33) > =09at java.util.TimerThread.mainLoop(Unknown Source) > =09at java.util.TimerThread.run(Unknown Source) > Caused by: java.lang.NullPointerException > =09at org.apache.activemq.leveldb.LevelDBClient$$anonfun$queueCursor$1.ap= ply(LevelDBClient.scala:1198) > =09at org.apache.activemq.leveldb.LevelDBClient$$anonfun$queueCursor$1.ap= ply(LevelDBClient.scala:1194) > =09at org.apache.activemq.leveldb.LevelDBClient$$anonfun$collectionCursor= $1$$anonfun$apply$mcV$sp$12.apply(LevelDBClient.scala:1272) > =09at org.apache.activemq.leveldb.LevelDBClient$$anonfun$collectionCursor= $1$$anonfun$apply$mcV$sp$12.apply(LevelDBClient.scala:1271) > =09at org.apache.activemq.leveldb.LevelDBClient$RichDB.check$4(LevelDBCli= ent.scala:315) -- This message was sent by Atlassian JIRA (v6.2#6252)