From dev-return-31824-apmail-activemq-dev-archive=activemq.apache.org@activemq.apache.org Thu Jun 14 20:59:43 2012 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 592119BDC for ; Thu, 14 Jun 2012 20:59:43 +0000 (UTC) Received: (qmail 93287 invoked by uid 500); 14 Jun 2012 20:59:43 -0000 Delivered-To: apmail-activemq-dev-archive@activemq.apache.org Received: (qmail 93257 invoked by uid 500); 14 Jun 2012 20:59:43 -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 93238 invoked by uid 99); 14 Jun 2012 20:59:43 -0000 Received: from issues-vm.apache.org (HELO issues-vm) (140.211.11.160) by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 14 Jun 2012 20:59:43 +0000 Received: from isssues-vm.apache.org (localhost [127.0.0.1]) by issues-vm (Postfix) with ESMTP id D82AC14002E for ; Thu, 14 Jun 2012 20:59:42 +0000 (UTC) Date: Thu, 14 Jun 2012 20:59:42 +0000 (UTC) From: "Gary Tully (JIRA)" To: dev@activemq.apache.org Message-ID: <1454973354.16993.1339707582888.JavaMail.jiratomcat@issues-vm> In-Reply-To: <1291997347.13908.1338337043228.JavaMail.jiratomcat@issues-vm> Subject: [jira] [Commented] (AMQ-3866) kahadb log files not getting cleaned up 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-3866?page=3Dcom.atlassian.j= ira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=3D132953= 12#comment-13295312 ]=20 Gary Tully commented on AMQ-3866: --------------------------------- the problem is:{code}2012-06-14 19:05:15,327 | TRACE | gc candidates after = first tx:2163:28949756, []{code} A transaction started in data file 2163 has not been completed, because the= transaction contents are not referenced by the index till the transaction = completes, we won't remove any data files that follow that one. So the question is what is the target destination and nature of that transa= ction, why is it not complete? Is there XA in the mix? Would it be possible to share/post that data file? If you have access to a debugger, one way to peek in would be to copy just = that data file to an alternative directory with no .data or .redo file and = allow an index to be rebuild just from that file by starting a broker refer= encing it. All entries will filter through:{code}org.apache.activemq.store.kahadb.Mess= ageDatabase#process{code} and you can watch for the location offest=3D=3D28= 949756 =20 > kahadb log files not getting cleaned up > --------------------------------------- > > Key: AMQ-3866 > URL: https://issues.apache.org/jira/browse/AMQ-3866 > Project: ActiveMQ > Issue Type: Bug > Components: Message Store > Affects Versions: 5.5.1, 5.6.0 > Reporter: Alexander Vallens > Priority: Critical > > A few weeks ago we experienced an event where several hundred thousand me= ssages were posted to a queue and slowly consumed over several days until a= ccidentally purged. Ever since then our kahadb has been growing on the orde= r of 12-20 bytes/10 seconds, corresponding to additional entries being adde= d to the kahadb log files that are not being cleaned up (this is even the c= ase in an isolated test environment with no subscribers/consumers/activity)= . Having searched and found AMQ-3131, AMQ-3736, AMQ-3424, we attempted an u= pgrade on a clone of the affected system from 5.5.1 to 5.6.0, with no luck.= Along the way here are the steps we took: > 1)=09I cloned our ActiveMQ virtual machine =E2=80=9Chot=E2=80=9D (i.e. wi= thout shutdown) and was able to get an isolated (different hostname, IP, VL= AN), but functioning, =E2=80=9Ccopy=E2=80=9D of the production ActiveMQ ins= tance > 2)=09startup is slow, given the sheer size of the kahadb, as shown in the= startup logging: > 2012-05-29 19:59:11,780 | INFO | Recovering from the journal ... | org.a= pache.activemq.store.kahadb.MessageDatabase | main > 2012-05-29 20:05:28,352 | WARN | Duplicate message add attempt rejected.= Destination: Consumer.SchedulerEvents.VirtualTopic.scheduler/events, Messa= ge id: ID:-55381-1337386136713-0:18:1:1:1 | org.apache.a > ctivemq.store.kahadb.MessageDatabase | main > 2012-05-29 20:05:28,494 | WARN | Duplicate message add attempt rejected.= Destination: Consumer.SchedulerEvents.VirtualTopic.scheduler/events, Messa= ge id: ID:-55381-1337386136713-0:25:1:1:1 | org.apache.a > ctivemq.store.kahadb.MessageDatabase | main > 2012-05-29 20:05:28,528 | WARN | Duplicate message add attempt rejected.= Destination: Consumer.SchedulerEvents.VirtualTopic.scheduler/events, Messa= ge id: ID:-55381-1337386136713-0:32:1:1:1 | org.apache.a > ctivemq.store.kahadb.MessageDatabase | main > 2012-05-29 20:05:34,513 | INFO | Recovery replayed 2325747 operations fr= om the journal in 382.795 seconds. | org.apache.activemq.store.kahadb.Messa= geDatabase | main > 3)=09I was able to eliminate the 3 =E2=80=9Cduplicate message=E2=80=9D wa= rnings by purging the =E2=80=9CConsumer.SchedulerEvents.VirtualTopic.schedu= ler/events=E2=80=9D queue (I suspect there were unconsumed messages, perhap= s partially uploaded, in that queue at time of clone) > 4)=09after the above steps, I was able to observe that kahadb continued t= o grow at the same rate as the actual production ActiveMQ instancw, ~12-20 = bytes every 10s > 5)=09during the first normal shutdown of activemq, I observed the followi= ng errors: > java.lang.IllegalStateException: PageFile is not loaded > at org.apache.kahadb.page.PageFile.assertLoaded(PageFile.java:715= ) > at org.apache.kahadb.page.PageFile.tx(PageFile.java:239) > at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStor= e.resetBatching(KahaDBStore.java:510) > at org.apache.activemq.store.ProxyMessageStore.resetBatching(Prox= yMessageStore.java:93) > at org.apache.activemq.broker.region.cursors.QueueStorePrefetch.r= esetBatch(QueueStorePrefetch.java:85) > at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.= stop(AbstractStoreCursor.java:67) > at org.apache.activemq.broker.region.cursors.StoreQueueCursor.sto= p(StoreQueueCursor.java:84) > at org.apache.activemq.broker.region.Queue.stop(Queue.java:872) > at org.apache.activemq.broker.region.AbstractRegion.stop(Abstract= Region.java:110) > at org.apache.activemq.util.ServiceStopper.stop(ServiceStopper.ja= va:41) > at org.apache.activemq.broker.region.RegionBroker.doStop(RegionBr= oker.java:729) > at org.apache.activemq.broker.jmx.ManagedRegionBroker.doStop(Mana= gedRegionBroker.java:113) > at org.apache.activemq.broker.region.RegionBroker.stop(RegionBrok= er.java:213) > at org.apache.activemq.broker.BrokerFilter.stop(BrokerFilter.java= :161) > at org.apache.activemq.broker.scheduler.SchedulerBroker.stop(Sche= dulerBroker.java:104) > at org.apache.activemq.broker.BrokerFilter.stop(BrokerFilter.java= :161) > at org.apache.activemq.broker.BrokerFilter.stop(BrokerFilter.java= :161) > at org.apache.activemq.broker.TransactionBroker.stop(TransactionB= roker.java:114) > at org.apache.activemq.broker.BrokerService$3.stop(BrokerService.= java:1795) > at org.apache.activemq.util.ServiceStopper.stop(ServiceStopper.ja= va:41) > at org.apache.activemq.broker.BrokerService.stop(BrokerService.ja= va:587) > at org.apache.activemq.console.command.StartCommand$1.run(StartCo= mmand.java:135) > 2012-05-29 20:22:09,112 | ERROR | Failed to reset batching | org.apache.a= ctivemq.store.kahadb.KahaDBStore | Thread-45 > 6)=09subsequent shutdowns, however, operated normally without error > 7)=09even after various attempts at shutdown and start back up, the afore= mentioned journal recovery was time consuming: > 2012-05-29 20:25:06,780 | INFO | Recovering from the journal ... | org.a= pache.activemq.store.kahadb.MessageDatabase | main > 2012-05-29 20:31:39,821 | INFO | Recovery replayed 2325954 operations fr= om the journal in 393.074 seconds. | org.apache.activemq.store.kahadb.Messa= geDatabase | main > 8)=09and the kahadb growth issue persisted > 9)=09I went ahead and successfully upgraded to ActiveMQ v5.6.0 (verified = queues & messages in scheduled queue survived upgrade) > 10)=09first attempt to start activemq after 5.6.0 upgrade included follow= ing errors: > 2012-05-29 20:55:36,825 | ERROR | Failed to start ActiveMQ JMS Message Br= oker (localhost, null). Reason: java.lang.NegativeArraySizeException | org.= apache.activemq.broker.BrokerService | main > java.lang.NegativeArraySizeException > at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTree= Node.java:188) > at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTree= Node.java:147) > at org.apache.kahadb.page.Transaction.load(Transaction.java:412) > at org.apache.kahadb.page.Transaction.load(Transaction.java:367) > at org.apache.kahadb.index.BTreeIndex.loadNode(BTreeIndex.java:26= 2) > at org.apache.kahadb.index.BTreeIndex.getRoot(BTreeIndex.java:174= ) > at org.apache.kahadb.index.BTreeIndex.iterator(BTreeIndex.java:22= 8) > at org.apache.activemq.store.kahadb.MessageDatabase$StoredDestina= tionMarshaller$1.execute(MessageDatabase.java:1654) > at org.apache.kahadb.page.Transaction.execute(Transaction.java:76= 9) > at org.apache.activemq.store.kahadb.MessageDatabase$StoredDestina= tionMarshaller.readPayload(MessageDatabase.java:1642) > at org.apache.activemq.store.kahadb.MessageDatabase$StoredDestina= tionMarshaller.readPayload(MessageDatabase.java:1627) > at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTree= Node.java:201) > at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTree= Node.java:147) > at org.apache.kahadb.page.Transaction.load(Transaction.java:412) > at org.apache.kahadb.page.Transaction.load(Transaction.java:367) > at org.apache.kahadb.index.BTreeIndex.loadNode(BTreeIndex.java:26= 2) > at org.apache.kahadb.index.BTreeIndex.getRoot(BTreeIndex.java:174= ) > at org.apache.kahadb.index.BTreeIndex.iterator(BTreeIndex.java:22= 8) > at org.apache.activemq.store.kahadb.KahaDBStore$6.execute(KahaDBS= tore.java:943) > at org.apache.kahadb.page.Transaction.execute(Transaction.java:76= 9) > at org.apache.activemq.store.kahadb.KahaDBStore.getDestinations(K= ahaDBStore.java:941) > at org.apache.activemq.store.kahadb.KahaDBPersistenceAdapter.getD= estinations(KahaDBPersistenceAdapter.java:122)=20 > at org.apache.activemq.broker.region.DestinationFactoryImpl.getDe= stinations(DestinationFactoryImpl.java:68) > at org.apache.activemq.broker.BrokerService.startVirtualConsumerD= estinations(BrokerService.java:2369) > at org.apache.activemq.broker.BrokerService.startDestinations(Bro= kerService.java:2198) > at org.apache.activemq.broker.BrokerService.start(BrokerService.j= ava:527) > at org.apache.activemq.xbean.XBeanBrokerService.afterPropertiesSe= t(XBeanBrokerService.java:60) > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) > at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccess= orImpl.java:39) > at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMeth= odAccessorImpl.java:25) > at java.lang.reflect.Method.invoke(Method.java:597) > at org.springframework.beans.factory.support.AbstractAutowireCapa= bleBeanFactory.invokeCustomInitMethod(AbstractAutowireCapableBeanFactory.ja= va:1544) > at org.springframework.beans.factory.support.AbstractAutowireCapa= bleBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:14= 85) > at org.springframework.beans.factory.support.AbstractAutowireCapa= bleBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1417) > at org.springframework.beans.factory.support.AbstractAutowireCapa= bleBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:519) > at org.springframework.beans.factory.support.AbstractAutowireCapa= bleBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:456) > at org.springframework.beans.factory.support.AbstractBeanFactory$= 1.getObject(AbstractBeanFactory.java:293) > at org.springframework.beans.factory.support.DefaultSingletonBean= Registry.getSingleton(DefaultSingletonBeanRegistry.java:222) > at org.springframework.beans.factory.support.AbstractBeanFactory.= doGetBean(AbstractBeanFactory.java:290) > at org.springframework.beans.factory.support.AbstractBeanFactory.= getBean(AbstractBeanFactory.java:192) > at org.springframework.beans.factory.support.DefaultListableBeanF= actory.preInstantiateSingletons(DefaultListableBeanFactory.java:585) > at org.springframework.context.support.AbstractApplicationContext= .finishBeanFactoryInitialization(AbstractApplicationContext.java:895) > at org.springframework.context.support.AbstractApplicationContext= .refresh(AbstractApplicationContext.java:425) > at org.apache.xbean.spring.context.ResourceXmlApplicationContext.= (ResourceXmlApplicationContext.java:64) > at org.apache.xbean.spring.context.ResourceXmlApplicationContext.= (ResourceXmlApplicationContext.java:52)=20 > at org.apache.activemq.xbean.XBeanBrokerFactory$1.(XBeanBro= kerFactory.java:108) > at org.apache.activemq.xbean.XBeanBrokerFactory.createApplication= Context(XBeanBrokerFactory.java:108) > at org.apache.activemq.xbean.XBeanBrokerFactory.createBroker(XBea= nBrokerFactory.java:72) > at org.apache.activemq.broker.BrokerFactory.createBroker(BrokerFa= ctory.java:71) > at org.apache.activemq.broker.BrokerFactory.createBroker(BrokerFa= ctory.java:54) > at org.apache.activemq.console.command.StartCommand.startBroker(S= tartCommand.java:115) > at org.apache.activemq.console.command.StartCommand.runTask(Start= Command.java:74) > at org.apache.activemq.console.command.AbstractCommand.execute(Ab= stractCommand.java:57) > at org.apache.activemq.console.command.ShellCommand.runTask(Shell= Command.java:148) > at org.apache.activemq.console.command.AbstractCommand.execute(Ab= stractCommand.java:57) > at org.apache.activemq.console.command.ShellCommand.main(ShellCom= mand.java:90) > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) > at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccess= orImpl.java:39) > at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMeth= odAccessorImpl.java:25) > at java.lang.reflect.Method.invoke(Method.java:597) > at org.apache.activemq.console.Main.runTaskClass(Main.java:257) > at org.apache.activemq.console.Main.main(Main.java:111) > 2012-05-29 20:55:36,873 | INFO | ActiveMQ Message Broker (localhost, nul= l) is shutting down | org.apache.activemq.broker.BrokerService | main > 2012-05-29 20:55:36,873 | INFO | Connector openwire Stopped | org.apache= .activemq.broker.TransportConnector | main > 2012-05-29 20:55:36,873 | INFO | Connector stomp Stopped | org.apache.ac= tivemq.broker.TransportConnector | main > 2012-05-29 20:55:36,897 | INFO | PListStore:[/opt/activemq/data/localhos= t/tmp_storage ] stopped | org.apache.activemq.store.kahadb.plist.PListStore= | main > 2012-05-29 20:55:36,897 | INFO | Stopping async queue tasks | org.apache= .activemq.store.kahadb.KahaDBStore | main > 2012-05-29 20:55:36,897 | INFO | Stopping async topic tasks | org.apache= .activemq.store.kahadb.KahaDBStore | main=20 > 2012-05-29 20:55:36,897 | INFO | Stopped KahaDB | org.apache.activemq.st= ore.kahadb.KahaDBStore | main > 2012-05-29 20:55:37,297 | INFO | ActiveMQ JMS Message Broker (localhost,= null) stopped | org.apache.activemq.broker.BrokerService | main > 2012-05-29 20:55:37,300 | ERROR | Failed to load: class path resource [ac= tivemq.xml], reason: Error creating bean with name 'org.apache.activemq.xbe= an.XBeanBrokerService#0' defined in class path resource [activemq.xml]: Inv= oc > ation of init method failed; nested exception is java.lang.NegativeArrayS= izeException | org.apache.activemq.xbean.XBeanBrokerFactory | main > org.springframework.beans.factory.BeanCreationException: Error creating b= ean with name 'org.apache.activemq.xbean.XBeanBrokerService#0' defined in c= lass path resource [activemq.xml]: Invocation of init method failed; nested= e > xception is java.lang.NegativeArraySizeException > at org.springframework.beans.factory.support.AbstractAutowireCapa= bleBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1420) > at org.springframework.beans.factory.support.AbstractAutowireCapa= bleBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:519) > at org.springframework.beans.factory.support.AbstractAutowireCapa= bleBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:456) > at org.springframework.beans.factory.support.AbstractBeanFactory$= 1.getObject(AbstractBeanFactory.java:293) > at org.springframework.beans.factory.support.DefaultSingletonBean= Registry.getSingleton(DefaultSingletonBeanRegistry.java:222) > at org.springframework.beans.factory.support.AbstractBeanFactory.= doGetBean(AbstractBeanFactory.java:290) > at org.springframework.beans.factory.support.AbstractBeanFactory.= getBean(AbstractBeanFactory.java:192) > at org.springframework.beans.factory.support.DefaultListableBeanF= actory.preInstantiateSingletons(DefaultListableBeanFactory.java:585) > at org.springframework.context.support.AbstractApplicationContext= .finishBeanFactoryInitialization(AbstractApplicationContext.java:895) > at org.springframework.context.support.AbstractApplicationContext= .refresh(AbstractApplicationContext.java:425) > at org.apache.xbean.spring.context.ResourceXmlApplicationContext.= (ResourceXmlApplicationContext.java:64) > at org.apache.xbean.spring.context.ResourceXmlApplicationContext.= (ResourceXmlApplicationContext.java:52) > at org.apache.activemq.xbean.XBeanBrokerFactory$1.(XBeanBro= kerFactory.java:108) > at org.apache.activemq.xbean.XBeanBrokerFactory.createApplication= Context(XBeanBrokerFactory.java:108) > at org.apache.activemq.xbean.XBeanBrokerFactory.createBroker(XBea= nBrokerFactory.java:72) > at org.apache.activemq.broker.BrokerFactory.createBroker(BrokerFa= ctory.java:71) > at org.apache.activemq.broker.BrokerFactory.createBroker(BrokerFa= ctory.java:54)=20 > at org.apache.activemq.console.command.StartCommand.startBroker(S= tartCommand.java:115) > at org.apache.activemq.console.command.StartCommand.runTask(Start= Command.java:74) > at org.apache.activemq.console.command.AbstractCommand.execute(Ab= stractCommand.java:57) > at org.apache.activemq.console.command.ShellCommand.runTask(Shell= Command.java:148) > at org.apache.activemq.console.command.AbstractCommand.execute(Ab= stractCommand.java:57) > at org.apache.activemq.console.command.ShellCommand.main(ShellCom= mand.java:90) > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) > at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccess= orImpl.java:39) > at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMeth= odAccessorImpl.java:25) > at java.lang.reflect.Method.invoke(Method.java:597) > at org.apache.activemq.console.Main.runTaskClass(Main.java:257) > at org.apache.activemq.console.Main.main(Main.java:111) > Caused by: java.lang.NegativeArraySizeException > at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTree= Node.java:188) > at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTree= Node.java:147) > at org.apache.kahadb.page.Transaction.load(Transaction.java:412) > at org.apache.kahadb.page.Transaction.load(Transaction.java:367) > at org.apache.kahadb.index.BTreeIndex.loadNode(BTreeIndex.java:26= 2) > at org.apache.kahadb.index.BTreeIndex.getRoot(BTreeIndex.java:174= ) > at org.apache.kahadb.index.BTreeIndex.iterator(BTreeIndex.java:22= 8) > at org.apache.activemq.store.kahadb.MessageDatabase$StoredDestina= tionMarshaller$1.execute(MessageDatabase.java:1654) > at org.apache.kahadb.page.Transaction.execute(Transaction.java:76= 9) > at org.apache.activemq.store.kahadb.MessageDatabase$StoredDestina= tionMarshaller.readPayload(MessageDatabase.java:1642)=20 > at org.apache.activemq.store.kahadb.MessageDatabase$StoredDestina= tionMarshaller.readPayload(MessageDatabase.java:1627) > at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTree= Node.java:201) > at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTree= Node.java:147) > at org.apache.kahadb.page.Transaction.load(Transaction.java:412) > at org.apache.kahadb.page.Transaction.load(Transaction.java:367) > at org.apache.kahadb.index.BTreeIndex.loadNode(BTreeIndex.java:26= 2) > at org.apache.kahadb.index.BTreeIndex.getRoot(BTreeIndex.java:174= ) > at org.apache.kahadb.index.BTreeIndex.iterator(BTreeIndex.java:22= 8) > at org.apache.activemq.store.kahadb.KahaDBStore$6.execute(KahaDBS= tore.java:943) > at org.apache.kahadb.page.Transaction.execute(Transaction.java:76= 9) > at org.apache.activemq.store.kahadb.KahaDBStore.getDestinations(K= ahaDBStore.java:941) > at org.apache.activemq.store.kahadb.KahaDBPersistenceAdapter.getD= estinations(KahaDBPersistenceAdapter.java:122) > at org.apache.activemq.broker.region.DestinationFactoryImpl.getDe= stinations(DestinationFactoryImpl.java:68) > at org.apache.activemq.broker.BrokerService.startVirtualConsumerD= estinations(BrokerService.java:2369) > at org.apache.activemq.broker.BrokerService.startDestinations(Bro= kerService.java:2198) > at org.apache.activemq.broker.BrokerService.start(BrokerService.j= ava:527) > at org.apache.activemq.xbean.XBeanBrokerService.afterPropertiesSe= t(XBeanBrokerService.java:60) > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) > at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccess= orImpl.java:39) > at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMeth= odAccessorImpl.java:25) > at java.lang.reflect.Method.invoke(Method.java:597) > at org.springframework.beans.factory.support.AbstractAutowireCapa= bleBeanFactory.invokeCustomInitMethod(AbstractAutowireCapableBeanFactory.ja= va:1544) > at org.springframework.beans.factory.support.AbstractAutowireCapa= bleBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:14= 85)=20 > at org.springframework.beans.factory.support.AbstractAutowireCapa= bleBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1417) > ... 28 more > 11)=09after the above errors, ActiveMQ was dead; another attempt to start= worked, yielding the following (also logged in previous attempt): > 2012-05-29 21:58:01,317 | INFO | KahaDB is version 4 | org.apache.active= mq.store.kahadb.MessageDatabase | main > 2012-05-29 21:58:01,396 | INFO | Recovering from the journal ... | org.a= pache.activemq.store.kahadb.MessageDatabase | main > 2012-05-29 21:58:27,601 | INFO | @2207:10939359, 100000 entries recovere= d .. | org.apache.activemq.store.kahadb.MessageDatabase | main > 2012-05-29 21:58:42,788 | INFO | @2222:10328575, 200000 entries recovere= d .. | org.apache.activemq.store.kahadb.MessageDatabase | main > 2012-05-29 21:58:59,234 | INFO | @2242:14360209, 300000 entries recovere= d .. | org.apache.activemq.store.kahadb.MessageDatabase | main > 2012-05-29 21:59:13,628 | INFO | @2254:1365404, 400000 entries recovered= .. | org.apache.activemq.store.kahadb.MessageDatabase | main > 2012-05-29 21:59:27,466 | INFO | @2264:30387363, 500000 entries recovere= d .. | org.apache.activemq.store.kahadb.MessageDatabase | main > 2012-05-29 21:59:43,739 | INFO | @2281:28756842, 600000 entries recovere= d .. | org.apache.activemq.store.kahadb.MessageDatabase | main > 2012-05-29 22:00:13,389 | INFO | @2320:26490711, 700000 entries recovere= d .. | org.apache.activemq.store.kahadb.MessageDatabase | main > 2012-05-29 22:00:47,350 | INFO | @2371:21837918, 800000 entries recovere= d .. | org.apache.activemq.store.kahadb.MessageDatabase | main > 2012-05-29 22:01:17,752 | INFO | @2412:10702462, 900000 entries recovere= d .. | org.apache.activemq.store.kahadb.MessageDatabase | main > 2012-05-29 22:01:51,288 | INFO | @2465:32070937, 1000000 entries recover= ed .. | org.apache.activemq.store.kahadb.MessageDatabase | main > 2012-05-29 22:02:25,203 | INFO | @2519:21797589, 1100000 entries recover= ed .. | org.apache.activemq.store.kahadb.MessageDatabase | main > 2012-05-29 22:02:55,188 | INFO | @2564:13289299, 1200000 entries recover= ed .. | org.apache.activemq.store.kahadb.MessageDatabase | main > 2012-05-29 22:03:05,786 | INFO | @2572:23712519, 1300000 entries recover= ed .. | org.apache.activemq.store.kahadb.MessageDatabase | main > 2012-05-29 22:03:15,375 | INFO | @2578:22618226, 1400000 entries recover= ed .. | org.apache.activemq.store.kahadb.MessageDatabase | main > 2012-05-29 22:03:27,246 | INFO | @2585:31399538, 1500000 entries recover= ed .. | org.apache.activemq.store.kahadb.MessageDatabase | main > 2012-05-29 22:03:38,213 | INFO | @2593:7102179, 1600000 entries recovere= d .. | org.apache.activemq.store.kahadb.MessageDatabase | main > 2012-05-29 22:03:48,285 | INFO | @2600:11040885, 1700000 entries recover= ed .. | org.apache.activemq.store.kahadb.MessageDatabase | main > 2012-05-29 22:03:55,053 | INFO | @2602:28573821, 1800000 entries recover= ed .. | org.apache.activemq.store.kahadb.MessageDatabase | main > 2012-05-29 22:04:01,331 | INFO | @2603:32850602, 1900000 entries recover= ed .. | org.apache.activemq.store.kahadb.MessageDatabase | main > 2012-05-29 22:04:06,689 | INFO | @2605:3582539, 2000000 entries recovere= d .. | org.apache.activemq.store.kahadb.MessageDatabase | main > 2012-05-29 22:04:12,435 | INFO | @2606:7920235, 2100000 entries recovere= d .. | org.apache.activemq.store.kahadb.MessageDatabase | main > 2012-05-29 22:04:17,500 | INFO | @2607:12248010, 2200000 entries recover= ed .. | org.apache.activemq.store.kahadb.MessageDatabase | main=20 > 2012-05-29 22:04:25,521 | INFO | @2617:28414362, 2300000 entries recover= ed .. | org.apache.activemq.store.kahadb.MessageDatabase | main > 2012-05-29 22:04:28,459 | INFO | Recovery replayed 2326036 operations fr= om the journal in 387.094 seconds. | org.apache.activemq.store.kahadb.Messa= geDatabase | main > 12)=09unfortunately, I confirmed that even after upgrade, kahadb continue= s to grow at about the same rate as before > 13) I then applied the logging parameters as described in http://activemq= .apache.org/why-do-kahadb-log-files-remain-after-cleanup.html. . With debug= ging spun up we see A LOT (I can=E2=80=99t get a count because log files ro= tate too fast, but in the 6 logs that remain I get 31,978 entries) of the f= ollowing: > 2012-05-29 23:18:41,925 | DEBUG | message not found in sequence id index:= ID:-59596-1337475432262-0:35:1:1:1202 | org.apache.activemq.store.ka= hadb.MessageDatabase | main > Google and a search on issues.apache.org reveal nothing on this. -- This message is automatically generated by JIRA. If you think it was sent incorrectly, please contact your JIRA administrato= rs: https://issues.apache.org/jira/secure/ContactAdministrators!default.jsp= a For more information on JIRA, see: http://www.atlassian.com/software/jira