You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@activemq.apache.org by "Alexander Vallens (JIRA)" <ji...@apache.org> on 2012/05/30 02:17:23 UTC
[jira] [Created] (AMQ-3866) kahadb log files not getting cleaned up
Alexander Vallens created AMQ-3866:
--------------------------------------
Summary: 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.6.0, 5.5.1
Reporter: Alexander Vallens
Priority: Critical
A few weeks ago we experienced an event where several hundred thousand messages were posted to a queue and slowly consumed over several days until accidentally purged. Ever since then our kahadb has been growing on the order of 12-20 bytes/10 seconds, corresponding to additional entries being added to the kahadb log files that are not being cleaned up (this is even the case in an isolated test environment with no subscribers/consumers/activity). Having searched and found AMQ-3131, AMQ-3736, AMQ-3424, we attempted an upgrade 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) I cloned our ActiveMQ virtual machine “hot” (i.e. without shutdown) and was able to get an isolated (different hostname, IP, VLAN), but functioning, “copy” of the production ActiveMQ instance
2) startup 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.apache.activemq.store.kahadb.MessageDatabase | main
2012-05-29 20:05:28,352 | WARN | Duplicate message add attempt rejected. Destination: Consumer.SchedulerEvents.VirtualTopic.scheduler/events, Message id: ID:<FQDN>-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, Message id: ID:<FQDN>-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, Message id: ID:<FQDN>-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 from the journal in 382.795 seconds. | org.apache.activemq.store.kahadb.MessageDatabase | main
3) I was able to eliminate the 3 “duplicate message” warnings by purging the “Consumer.SchedulerEvents.VirtualTopic.scheduler/events” queue (I suspect there were unconsumed messages, perhaps partially uploaded, in that queue at time of clone)
4) after the above steps, I was able to observe that kahadb continued to grow at the same rate as the actual production ActiveMQ instancw, ~12-20 bytes every 10s
5) during the first normal shutdown of activemq, I observed the following 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$KahaDBMessageStore.resetBatching(KahaDBStore.java:510)
at org.apache.activemq.store.ProxyMessageStore.resetBatching(ProxyMessageStore.java:93)
at org.apache.activemq.broker.region.cursors.QueueStorePrefetch.resetBatch(QueueStorePrefetch.java:85)
at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.stop(AbstractStoreCursor.java:67)
at org.apache.activemq.broker.region.cursors.StoreQueueCursor.stop(StoreQueueCursor.java:84)
at org.apache.activemq.broker.region.Queue.stop(Queue.java:872)
at org.apache.activemq.broker.region.AbstractRegion.stop(AbstractRegion.java:110)
at org.apache.activemq.util.ServiceStopper.stop(ServiceStopper.java:41)
at org.apache.activemq.broker.region.RegionBroker.doStop(RegionBroker.java:729)
at org.apache.activemq.broker.jmx.ManagedRegionBroker.doStop(ManagedRegionBroker.java:113)
at org.apache.activemq.broker.region.RegionBroker.stop(RegionBroker.java:213)
at org.apache.activemq.broker.BrokerFilter.stop(BrokerFilter.java:161)
at org.apache.activemq.broker.scheduler.SchedulerBroker.stop(SchedulerBroker.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(TransactionBroker.java:114)
at org.apache.activemq.broker.BrokerService$3.stop(BrokerService.java:1795)
at org.apache.activemq.util.ServiceStopper.stop(ServiceStopper.java:41)
at org.apache.activemq.broker.BrokerService.stop(BrokerService.java:587)
at org.apache.activemq.console.command.StartCommand$1.run(StartCommand.java:135)
2012-05-29 20:22:09,112 | ERROR | Failed to reset batching | org.apache.activemq.store.kahadb.KahaDBStore | Thread-45
6) subsequent shutdowns, however, operated normally without error
7) even after various attempts at shutdown and start back up, the aforementioned journal recovery was time consuming:
2012-05-29 20:25:06,780 | INFO | Recovering from the journal ... | org.apache.activemq.store.kahadb.MessageDatabase | main
2012-05-29 20:31:39,821 | INFO | Recovery replayed 2325954 operations from the journal in 393.074 seconds. | org.apache.activemq.store.kahadb.MessageDatabase | main
8) and the kahadb growth issue persisted
9) I went ahead and successfully upgraded to ActiveMQ v5.6.0 (verified queues & messages in scheduled queue survived upgrade)
10) first attempt to start activemq after 5.6.0 upgrade included following errors:
2012-05-29 20:55:36,825 | ERROR | Failed to start ActiveMQ JMS Message Broker (localhost, null). Reason: java.lang.NegativeArraySizeException | org.apache.activemq.broker.BrokerService | main
java.lang.NegativeArraySizeException
at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTreeNode.java:188)
at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTreeNode.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:262)
at org.apache.kahadb.index.BTreeIndex.getRoot(BTreeIndex.java:174)
at org.apache.kahadb.index.BTreeIndex.iterator(BTreeIndex.java:228)
at org.apache.activemq.store.kahadb.MessageDatabase$StoredDestinationMarshaller$1.execute(MessageDatabase.java:1654)
at org.apache.kahadb.page.Transaction.execute(Transaction.java:769)
at org.apache.activemq.store.kahadb.MessageDatabase$StoredDestinationMarshaller.readPayload(MessageDatabase.java:1642)
at org.apache.activemq.store.kahadb.MessageDatabase$StoredDestinationMarshaller.readPayload(MessageDatabase.java:1627)
at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTreeNode.java:201)
at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTreeNode.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:262)
at org.apache.kahadb.index.BTreeIndex.getRoot(BTreeIndex.java:174)
at org.apache.kahadb.index.BTreeIndex.iterator(BTreeIndex.java:228)
at org.apache.activemq.store.kahadb.KahaDBStore$6.execute(KahaDBStore.java:943)
at org.apache.kahadb.page.Transaction.execute(Transaction.java:769)
at org.apache.activemq.store.kahadb.KahaDBStore.getDestinations(KahaDBStore.java:941)
at org.apache.activemq.store.kahadb.KahaDBPersistenceAdapter.getDestinations(KahaDBPersistenceAdapter.java:122)
at org.apache.activemq.broker.region.DestinationFactoryImpl.getDestinations(DestinationFactoryImpl.java:68)
at org.apache.activemq.broker.BrokerService.startVirtualConsumerDestinations(BrokerService.java:2369)
at org.apache.activemq.broker.BrokerService.startDestinations(BrokerService.java:2198)
at org.apache.activemq.broker.BrokerService.start(BrokerService.java:527)
at org.apache.activemq.xbean.XBeanBrokerService.afterPropertiesSet(XBeanBrokerService.java:60)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeCustomInitMethod(AbstractAutowireCapableBeanFactory.java:1544)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1485)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1417)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:519)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:456)
at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:293)
at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.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.DefaultListableBeanFactory.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.<init>(ResourceXmlApplicationContext.java:64)
at org.apache.xbean.spring.context.ResourceXmlApplicationContext.<init>(ResourceXmlApplicationContext.java:52)
at org.apache.activemq.xbean.XBeanBrokerFactory$1.<init>(XBeanBrokerFactory.java:108)
at org.apache.activemq.xbean.XBeanBrokerFactory.createApplicationContext(XBeanBrokerFactory.java:108)
at org.apache.activemq.xbean.XBeanBrokerFactory.createBroker(XBeanBrokerFactory.java:72)
at org.apache.activemq.broker.BrokerFactory.createBroker(BrokerFactory.java:71)
at org.apache.activemq.broker.BrokerFactory.createBroker(BrokerFactory.java:54)
at org.apache.activemq.console.command.StartCommand.startBroker(StartCommand.java:115)
at org.apache.activemq.console.command.StartCommand.runTask(StartCommand.java:74)
at org.apache.activemq.console.command.AbstractCommand.execute(AbstractCommand.java:57)
at org.apache.activemq.console.command.ShellCommand.runTask(ShellCommand.java:148)
at org.apache.activemq.console.command.AbstractCommand.execute(AbstractCommand.java:57)
at org.apache.activemq.console.command.ShellCommand.main(ShellCommand.java:90)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.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, null) 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.activemq.broker.TransportConnector | main
2012-05-29 20:55:36,897 | INFO | PListStore:[/opt/activemq/data/localhost/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
2012-05-29 20:55:36,897 | INFO | Stopped KahaDB | org.apache.activemq.store.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 [activemq.xml], reason: Error creating bean with name 'org.apache.activemq.xbean.XBeanBrokerService#0' defined in class path resource [activemq.xml]: Invoc
ation of init method failed; nested exception is java.lang.NegativeArraySizeException | org.apache.activemq.xbean.XBeanBrokerFactory | main
org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'org.apache.activemq.xbean.XBeanBrokerService#0' defined in class path resource [activemq.xml]: Invocation of init method failed; nested e
xception is java.lang.NegativeArraySizeException
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1420)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:519)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:456)
at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:293)
at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.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.DefaultListableBeanFactory.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.<init>(ResourceXmlApplicationContext.java:64)
at org.apache.xbean.spring.context.ResourceXmlApplicationContext.<init>(ResourceXmlApplicationContext.java:52)
at org.apache.activemq.xbean.XBeanBrokerFactory$1.<init>(XBeanBrokerFactory.java:108)
at org.apache.activemq.xbean.XBeanBrokerFactory.createApplicationContext(XBeanBrokerFactory.java:108)
at org.apache.activemq.xbean.XBeanBrokerFactory.createBroker(XBeanBrokerFactory.java:72)
at org.apache.activemq.broker.BrokerFactory.createBroker(BrokerFactory.java:71)
at org.apache.activemq.broker.BrokerFactory.createBroker(BrokerFactory.java:54)
at org.apache.activemq.console.command.StartCommand.startBroker(StartCommand.java:115)
at org.apache.activemq.console.command.StartCommand.runTask(StartCommand.java:74)
at org.apache.activemq.console.command.AbstractCommand.execute(AbstractCommand.java:57)
at org.apache.activemq.console.command.ShellCommand.runTask(ShellCommand.java:148)
at org.apache.activemq.console.command.AbstractCommand.execute(AbstractCommand.java:57)
at org.apache.activemq.console.command.ShellCommand.main(ShellCommand.java:90)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.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(BTreeNode.java:188)
at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTreeNode.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:262)
at org.apache.kahadb.index.BTreeIndex.getRoot(BTreeIndex.java:174)
at org.apache.kahadb.index.BTreeIndex.iterator(BTreeIndex.java:228)
at org.apache.activemq.store.kahadb.MessageDatabase$StoredDestinationMarshaller$1.execute(MessageDatabase.java:1654)
at org.apache.kahadb.page.Transaction.execute(Transaction.java:769)
at org.apache.activemq.store.kahadb.MessageDatabase$StoredDestinationMarshaller.readPayload(MessageDatabase.java:1642)
at org.apache.activemq.store.kahadb.MessageDatabase$StoredDestinationMarshaller.readPayload(MessageDatabase.java:1627)
at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTreeNode.java:201)
at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTreeNode.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:262)
at org.apache.kahadb.index.BTreeIndex.getRoot(BTreeIndex.java:174)
at org.apache.kahadb.index.BTreeIndex.iterator(BTreeIndex.java:228)
at org.apache.activemq.store.kahadb.KahaDBStore$6.execute(KahaDBStore.java:943)
at org.apache.kahadb.page.Transaction.execute(Transaction.java:769)
at org.apache.activemq.store.kahadb.KahaDBStore.getDestinations(KahaDBStore.java:941)
at org.apache.activemq.store.kahadb.KahaDBPersistenceAdapter.getDestinations(KahaDBPersistenceAdapter.java:122)
at org.apache.activemq.broker.region.DestinationFactoryImpl.getDestinations(DestinationFactoryImpl.java:68)
at org.apache.activemq.broker.BrokerService.startVirtualConsumerDestinations(BrokerService.java:2369)
at org.apache.activemq.broker.BrokerService.startDestinations(BrokerService.java:2198)
at org.apache.activemq.broker.BrokerService.start(BrokerService.java:527)
at org.apache.activemq.xbean.XBeanBrokerService.afterPropertiesSet(XBeanBrokerService.java:60)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeCustomInitMethod(AbstractAutowireCapableBeanFactory.java:1544)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1485)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1417)
... 28 more
11) after 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.activemq.store.kahadb.MessageDatabase | main
2012-05-29 21:58:01,396 | INFO | Recovering from the journal ... | org.apache.activemq.store.kahadb.MessageDatabase | main
2012-05-29 21:58:27,601 | INFO | @2207:10939359, 100000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
2012-05-29 21:58:42,788 | INFO | @2222:10328575, 200000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
2012-05-29 21:58:59,234 | INFO | @2242:14360209, 300000 entries recovered .. | 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 recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
2012-05-29 21:59:43,739 | INFO | @2281:28756842, 600000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
2012-05-29 22:00:13,389 | INFO | @2320:26490711, 700000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
2012-05-29 22:00:47,350 | INFO | @2371:21837918, 800000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
2012-05-29 22:01:17,752 | INFO | @2412:10702462, 900000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
2012-05-29 22:01:51,288 | INFO | @2465:32070937, 1000000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
2012-05-29 22:02:25,203 | INFO | @2519:21797589, 1100000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
2012-05-29 22:02:55,188 | INFO | @2564:13289299, 1200000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
2012-05-29 22:03:05,786 | INFO | @2572:23712519, 1300000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
2012-05-29 22:03:15,375 | INFO | @2578:22618226, 1400000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
2012-05-29 22:03:27,246 | INFO | @2585:31399538, 1500000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
2012-05-29 22:03:38,213 | INFO | @2593:7102179, 1600000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
2012-05-29 22:03:48,285 | INFO | @2600:11040885, 1700000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
2012-05-29 22:03:55,053 | INFO | @2602:28573821, 1800000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
2012-05-29 22:04:01,331 | INFO | @2603:32850602, 1900000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
2012-05-29 22:04:06,689 | INFO | @2605:3582539, 2000000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
2012-05-29 22:04:12,435 | INFO | @2606:7920235, 2100000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
2012-05-29 22:04:17,500 | INFO | @2607:12248010, 2200000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
2012-05-29 22:04:25,521 | INFO | @2617:28414362, 2300000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
2012-05-29 22:04:28,459 | INFO | Recovery replayed 2326036 operations from the journal in 387.094 seconds. | org.apache.activemq.store.kahadb.MessageDatabase | main
12) unfortunately, I confirmed that even after upgrade, kahadb continues 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 debugging spun up we see A LOT (I can’t get a count because log files rotate too fast, but in the 6 logs that remain I get 31,978 entries) of the following:
2012-05-29 23:18:41,925 | DEBUG | message not found in sequence id index: ID:<FQDN>-59596-1337475432262-0:35:1:1:1202 | org.apache.activemq.store.kahadb.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 administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (AMQ-3866) kahadb log files not getting cleaned
up
Posted by "Gary Tully (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/AMQ-3866?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13294961#comment-13294961 ]
Gary Tully commented on AMQ-3866:
---------------------------------
There is a periodic checkpoint of the producer audit to the journal, this could be the reason for the increase in size but it would not prevent an unreferenced journal data file form getting removed.
First thing to do is recreate the index by replaying the journal from the start. Do this by stopping the broker, deleting the db.data and db.redo file in the kahadb persistence adapter directory and restarting.
This will ensure that the index is correct after the upgrade to 5.6
The key to understanding why a data file remains in your point 13) - but the information w.r.t to garbage collection is lost in those entries about the sequenceid index. I think with a rebuild of the index, those should disappear.
> 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 messages were posted to a queue and slowly consumed over several days until accidentally purged. Ever since then our kahadb has been growing on the order of 12-20 bytes/10 seconds, corresponding to additional entries being added to the kahadb log files that are not being cleaned up (this is even the case in an isolated test environment with no subscribers/consumers/activity). Having searched and found AMQ-3131, AMQ-3736, AMQ-3424, we attempted an upgrade 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) I cloned our ActiveMQ virtual machine “hot” (i.e. without shutdown) and was able to get an isolated (different hostname, IP, VLAN), but functioning, “copy” of the production ActiveMQ instance
> 2) startup 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.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 20:05:28,352 | WARN | Duplicate message add attempt rejected. Destination: Consumer.SchedulerEvents.VirtualTopic.scheduler/events, Message id: ID:<FQDN>-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, Message id: ID:<FQDN>-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, Message id: ID:<FQDN>-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 from the journal in 382.795 seconds. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 3) I was able to eliminate the 3 “duplicate message” warnings by purging the “Consumer.SchedulerEvents.VirtualTopic.scheduler/events” queue (I suspect there were unconsumed messages, perhaps partially uploaded, in that queue at time of clone)
> 4) after the above steps, I was able to observe that kahadb continued to grow at the same rate as the actual production ActiveMQ instancw, ~12-20 bytes every 10s
> 5) during the first normal shutdown of activemq, I observed the following 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$KahaDBMessageStore.resetBatching(KahaDBStore.java:510)
> at org.apache.activemq.store.ProxyMessageStore.resetBatching(ProxyMessageStore.java:93)
> at org.apache.activemq.broker.region.cursors.QueueStorePrefetch.resetBatch(QueueStorePrefetch.java:85)
> at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.stop(AbstractStoreCursor.java:67)
> at org.apache.activemq.broker.region.cursors.StoreQueueCursor.stop(StoreQueueCursor.java:84)
> at org.apache.activemq.broker.region.Queue.stop(Queue.java:872)
> at org.apache.activemq.broker.region.AbstractRegion.stop(AbstractRegion.java:110)
> at org.apache.activemq.util.ServiceStopper.stop(ServiceStopper.java:41)
> at org.apache.activemq.broker.region.RegionBroker.doStop(RegionBroker.java:729)
> at org.apache.activemq.broker.jmx.ManagedRegionBroker.doStop(ManagedRegionBroker.java:113)
> at org.apache.activemq.broker.region.RegionBroker.stop(RegionBroker.java:213)
> at org.apache.activemq.broker.BrokerFilter.stop(BrokerFilter.java:161)
> at org.apache.activemq.broker.scheduler.SchedulerBroker.stop(SchedulerBroker.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(TransactionBroker.java:114)
> at org.apache.activemq.broker.BrokerService$3.stop(BrokerService.java:1795)
> at org.apache.activemq.util.ServiceStopper.stop(ServiceStopper.java:41)
> at org.apache.activemq.broker.BrokerService.stop(BrokerService.java:587)
> at org.apache.activemq.console.command.StartCommand$1.run(StartCommand.java:135)
> 2012-05-29 20:22:09,112 | ERROR | Failed to reset batching | org.apache.activemq.store.kahadb.KahaDBStore | Thread-45
> 6) subsequent shutdowns, however, operated normally without error
> 7) even after various attempts at shutdown and start back up, the aforementioned journal recovery was time consuming:
> 2012-05-29 20:25:06,780 | INFO | Recovering from the journal ... | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 20:31:39,821 | INFO | Recovery replayed 2325954 operations from the journal in 393.074 seconds. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 8) and the kahadb growth issue persisted
> 9) I went ahead and successfully upgraded to ActiveMQ v5.6.0 (verified queues & messages in scheduled queue survived upgrade)
> 10) first attempt to start activemq after 5.6.0 upgrade included following errors:
> 2012-05-29 20:55:36,825 | ERROR | Failed to start ActiveMQ JMS Message Broker (localhost, null). Reason: java.lang.NegativeArraySizeException | org.apache.activemq.broker.BrokerService | main
> java.lang.NegativeArraySizeException
> at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTreeNode.java:188)
> at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTreeNode.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:262)
> at org.apache.kahadb.index.BTreeIndex.getRoot(BTreeIndex.java:174)
> at org.apache.kahadb.index.BTreeIndex.iterator(BTreeIndex.java:228)
> at org.apache.activemq.store.kahadb.MessageDatabase$StoredDestinationMarshaller$1.execute(MessageDatabase.java:1654)
> at org.apache.kahadb.page.Transaction.execute(Transaction.java:769)
> at org.apache.activemq.store.kahadb.MessageDatabase$StoredDestinationMarshaller.readPayload(MessageDatabase.java:1642)
> at org.apache.activemq.store.kahadb.MessageDatabase$StoredDestinationMarshaller.readPayload(MessageDatabase.java:1627)
> at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTreeNode.java:201)
> at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTreeNode.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:262)
> at org.apache.kahadb.index.BTreeIndex.getRoot(BTreeIndex.java:174)
> at org.apache.kahadb.index.BTreeIndex.iterator(BTreeIndex.java:228)
> at org.apache.activemq.store.kahadb.KahaDBStore$6.execute(KahaDBStore.java:943)
> at org.apache.kahadb.page.Transaction.execute(Transaction.java:769)
> at org.apache.activemq.store.kahadb.KahaDBStore.getDestinations(KahaDBStore.java:941)
> at org.apache.activemq.store.kahadb.KahaDBPersistenceAdapter.getDestinations(KahaDBPersistenceAdapter.java:122)
> at org.apache.activemq.broker.region.DestinationFactoryImpl.getDestinations(DestinationFactoryImpl.java:68)
> at org.apache.activemq.broker.BrokerService.startVirtualConsumerDestinations(BrokerService.java:2369)
> at org.apache.activemq.broker.BrokerService.startDestinations(BrokerService.java:2198)
> at org.apache.activemq.broker.BrokerService.start(BrokerService.java:527)
> at org.apache.activemq.xbean.XBeanBrokerService.afterPropertiesSet(XBeanBrokerService.java:60)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> at java.lang.reflect.Method.invoke(Method.java:597)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeCustomInitMethod(AbstractAutowireCapableBeanFactory.java:1544)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1485)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1417)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:519)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:456)
> at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:293)
> at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.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.DefaultListableBeanFactory.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.<init>(ResourceXmlApplicationContext.java:64)
> at org.apache.xbean.spring.context.ResourceXmlApplicationContext.<init>(ResourceXmlApplicationContext.java:52)
> at org.apache.activemq.xbean.XBeanBrokerFactory$1.<init>(XBeanBrokerFactory.java:108)
> at org.apache.activemq.xbean.XBeanBrokerFactory.createApplicationContext(XBeanBrokerFactory.java:108)
> at org.apache.activemq.xbean.XBeanBrokerFactory.createBroker(XBeanBrokerFactory.java:72)
> at org.apache.activemq.broker.BrokerFactory.createBroker(BrokerFactory.java:71)
> at org.apache.activemq.broker.BrokerFactory.createBroker(BrokerFactory.java:54)
> at org.apache.activemq.console.command.StartCommand.startBroker(StartCommand.java:115)
> at org.apache.activemq.console.command.StartCommand.runTask(StartCommand.java:74)
> at org.apache.activemq.console.command.AbstractCommand.execute(AbstractCommand.java:57)
> at org.apache.activemq.console.command.ShellCommand.runTask(ShellCommand.java:148)
> at org.apache.activemq.console.command.AbstractCommand.execute(AbstractCommand.java:57)
> at org.apache.activemq.console.command.ShellCommand.main(ShellCommand.java:90)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.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, null) 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.activemq.broker.TransportConnector | main
> 2012-05-29 20:55:36,897 | INFO | PListStore:[/opt/activemq/data/localhost/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
> 2012-05-29 20:55:36,897 | INFO | Stopped KahaDB | org.apache.activemq.store.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 [activemq.xml], reason: Error creating bean with name 'org.apache.activemq.xbean.XBeanBrokerService#0' defined in class path resource [activemq.xml]: Invoc
> ation of init method failed; nested exception is java.lang.NegativeArraySizeException | org.apache.activemq.xbean.XBeanBrokerFactory | main
> org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'org.apache.activemq.xbean.XBeanBrokerService#0' defined in class path resource [activemq.xml]: Invocation of init method failed; nested e
> xception is java.lang.NegativeArraySizeException
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1420)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:519)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:456)
> at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:293)
> at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.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.DefaultListableBeanFactory.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.<init>(ResourceXmlApplicationContext.java:64)
> at org.apache.xbean.spring.context.ResourceXmlApplicationContext.<init>(ResourceXmlApplicationContext.java:52)
> at org.apache.activemq.xbean.XBeanBrokerFactory$1.<init>(XBeanBrokerFactory.java:108)
> at org.apache.activemq.xbean.XBeanBrokerFactory.createApplicationContext(XBeanBrokerFactory.java:108)
> at org.apache.activemq.xbean.XBeanBrokerFactory.createBroker(XBeanBrokerFactory.java:72)
> at org.apache.activemq.broker.BrokerFactory.createBroker(BrokerFactory.java:71)
> at org.apache.activemq.broker.BrokerFactory.createBroker(BrokerFactory.java:54)
> at org.apache.activemq.console.command.StartCommand.startBroker(StartCommand.java:115)
> at org.apache.activemq.console.command.StartCommand.runTask(StartCommand.java:74)
> at org.apache.activemq.console.command.AbstractCommand.execute(AbstractCommand.java:57)
> at org.apache.activemq.console.command.ShellCommand.runTask(ShellCommand.java:148)
> at org.apache.activemq.console.command.AbstractCommand.execute(AbstractCommand.java:57)
> at org.apache.activemq.console.command.ShellCommand.main(ShellCommand.java:90)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.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(BTreeNode.java:188)
> at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTreeNode.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:262)
> at org.apache.kahadb.index.BTreeIndex.getRoot(BTreeIndex.java:174)
> at org.apache.kahadb.index.BTreeIndex.iterator(BTreeIndex.java:228)
> at org.apache.activemq.store.kahadb.MessageDatabase$StoredDestinationMarshaller$1.execute(MessageDatabase.java:1654)
> at org.apache.kahadb.page.Transaction.execute(Transaction.java:769)
> at org.apache.activemq.store.kahadb.MessageDatabase$StoredDestinationMarshaller.readPayload(MessageDatabase.java:1642)
> at org.apache.activemq.store.kahadb.MessageDatabase$StoredDestinationMarshaller.readPayload(MessageDatabase.java:1627)
> at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTreeNode.java:201)
> at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTreeNode.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:262)
> at org.apache.kahadb.index.BTreeIndex.getRoot(BTreeIndex.java:174)
> at org.apache.kahadb.index.BTreeIndex.iterator(BTreeIndex.java:228)
> at org.apache.activemq.store.kahadb.KahaDBStore$6.execute(KahaDBStore.java:943)
> at org.apache.kahadb.page.Transaction.execute(Transaction.java:769)
> at org.apache.activemq.store.kahadb.KahaDBStore.getDestinations(KahaDBStore.java:941)
> at org.apache.activemq.store.kahadb.KahaDBPersistenceAdapter.getDestinations(KahaDBPersistenceAdapter.java:122)
> at org.apache.activemq.broker.region.DestinationFactoryImpl.getDestinations(DestinationFactoryImpl.java:68)
> at org.apache.activemq.broker.BrokerService.startVirtualConsumerDestinations(BrokerService.java:2369)
> at org.apache.activemq.broker.BrokerService.startDestinations(BrokerService.java:2198)
> at org.apache.activemq.broker.BrokerService.start(BrokerService.java:527)
> at org.apache.activemq.xbean.XBeanBrokerService.afterPropertiesSet(XBeanBrokerService.java:60)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> at java.lang.reflect.Method.invoke(Method.java:597)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeCustomInitMethod(AbstractAutowireCapableBeanFactory.java:1544)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1485)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1417)
> ... 28 more
> 11) after 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.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 21:58:01,396 | INFO | Recovering from the journal ... | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 21:58:27,601 | INFO | @2207:10939359, 100000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 21:58:42,788 | INFO | @2222:10328575, 200000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 21:58:59,234 | INFO | @2242:14360209, 300000 entries recovered .. | 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 recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 21:59:43,739 | INFO | @2281:28756842, 600000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:00:13,389 | INFO | @2320:26490711, 700000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:00:47,350 | INFO | @2371:21837918, 800000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:01:17,752 | INFO | @2412:10702462, 900000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:01:51,288 | INFO | @2465:32070937, 1000000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:02:25,203 | INFO | @2519:21797589, 1100000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:02:55,188 | INFO | @2564:13289299, 1200000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:03:05,786 | INFO | @2572:23712519, 1300000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:03:15,375 | INFO | @2578:22618226, 1400000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:03:27,246 | INFO | @2585:31399538, 1500000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:03:38,213 | INFO | @2593:7102179, 1600000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:03:48,285 | INFO | @2600:11040885, 1700000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:03:55,053 | INFO | @2602:28573821, 1800000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:04:01,331 | INFO | @2603:32850602, 1900000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:04:06,689 | INFO | @2605:3582539, 2000000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:04:12,435 | INFO | @2606:7920235, 2100000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:04:17,500 | INFO | @2607:12248010, 2200000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:04:25,521 | INFO | @2617:28414362, 2300000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:04:28,459 | INFO | Recovery replayed 2326036 operations from the journal in 387.094 seconds. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 12) unfortunately, I confirmed that even after upgrade, kahadb continues 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 debugging spun up we see A LOT (I can’t get a count because log files rotate too fast, but in the 6 logs that remain I get 31,978 entries) of the following:
> 2012-05-29 23:18:41,925 | DEBUG | message not found in sequence id index: ID:<FQDN>-59596-1337475432262-0:35:1:1:1202 | org.apache.activemq.store.kahadb.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 administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Closed] (AMQ-3866) kahadb log files not getting cleaned up
Posted by "Timothy Bish (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/AMQ-3866?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Timothy Bish closed AMQ-3866.
-----------------------------
Resolution: Incomplete
No further information provided by the user in regards to the suggested solutions.
> 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 messages were posted to a queue and slowly consumed over several days until accidentally purged. Ever since then our kahadb has been growing on the order of 12-20 bytes/10 seconds, corresponding to additional entries being added to the kahadb log files that are not being cleaned up (this is even the case in an isolated test environment with no subscribers/consumers/activity). Having searched and found AMQ-3131, AMQ-3736, AMQ-3424, we attempted an upgrade 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) I cloned our ActiveMQ virtual machine “hot” (i.e. without shutdown) and was able to get an isolated (different hostname, IP, VLAN), but functioning, “copy” of the production ActiveMQ instance
> 2) startup 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.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 20:05:28,352 | WARN | Duplicate message add attempt rejected. Destination: Consumer.SchedulerEvents.VirtualTopic.scheduler/events, Message id: ID:<FQDN>-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, Message id: ID:<FQDN>-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, Message id: ID:<FQDN>-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 from the journal in 382.795 seconds. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 3) I was able to eliminate the 3 “duplicate message” warnings by purging the “Consumer.SchedulerEvents.VirtualTopic.scheduler/events” queue (I suspect there were unconsumed messages, perhaps partially uploaded, in that queue at time of clone)
> 4) after the above steps, I was able to observe that kahadb continued to grow at the same rate as the actual production ActiveMQ instancw, ~12-20 bytes every 10s
> 5) during the first normal shutdown of activemq, I observed the following 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$KahaDBMessageStore.resetBatching(KahaDBStore.java:510)
> at org.apache.activemq.store.ProxyMessageStore.resetBatching(ProxyMessageStore.java:93)
> at org.apache.activemq.broker.region.cursors.QueueStorePrefetch.resetBatch(QueueStorePrefetch.java:85)
> at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.stop(AbstractStoreCursor.java:67)
> at org.apache.activemq.broker.region.cursors.StoreQueueCursor.stop(StoreQueueCursor.java:84)
> at org.apache.activemq.broker.region.Queue.stop(Queue.java:872)
> at org.apache.activemq.broker.region.AbstractRegion.stop(AbstractRegion.java:110)
> at org.apache.activemq.util.ServiceStopper.stop(ServiceStopper.java:41)
> at org.apache.activemq.broker.region.RegionBroker.doStop(RegionBroker.java:729)
> at org.apache.activemq.broker.jmx.ManagedRegionBroker.doStop(ManagedRegionBroker.java:113)
> at org.apache.activemq.broker.region.RegionBroker.stop(RegionBroker.java:213)
> at org.apache.activemq.broker.BrokerFilter.stop(BrokerFilter.java:161)
> at org.apache.activemq.broker.scheduler.SchedulerBroker.stop(SchedulerBroker.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(TransactionBroker.java:114)
> at org.apache.activemq.broker.BrokerService$3.stop(BrokerService.java:1795)
> at org.apache.activemq.util.ServiceStopper.stop(ServiceStopper.java:41)
> at org.apache.activemq.broker.BrokerService.stop(BrokerService.java:587)
> at org.apache.activemq.console.command.StartCommand$1.run(StartCommand.java:135)
> 2012-05-29 20:22:09,112 | ERROR | Failed to reset batching | org.apache.activemq.store.kahadb.KahaDBStore | Thread-45
> 6) subsequent shutdowns, however, operated normally without error
> 7) even after various attempts at shutdown and start back up, the aforementioned journal recovery was time consuming:
> 2012-05-29 20:25:06,780 | INFO | Recovering from the journal ... | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 20:31:39,821 | INFO | Recovery replayed 2325954 operations from the journal in 393.074 seconds. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 8) and the kahadb growth issue persisted
> 9) I went ahead and successfully upgraded to ActiveMQ v5.6.0 (verified queues & messages in scheduled queue survived upgrade)
> 10) first attempt to start activemq after 5.6.0 upgrade included following errors:
> 2012-05-29 20:55:36,825 | ERROR | Failed to start ActiveMQ JMS Message Broker (localhost, null). Reason: java.lang.NegativeArraySizeException | org.apache.activemq.broker.BrokerService | main
> java.lang.NegativeArraySizeException
> at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTreeNode.java:188)
> at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTreeNode.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:262)
> at org.apache.kahadb.index.BTreeIndex.getRoot(BTreeIndex.java:174)
> at org.apache.kahadb.index.BTreeIndex.iterator(BTreeIndex.java:228)
> at org.apache.activemq.store.kahadb.MessageDatabase$StoredDestinationMarshaller$1.execute(MessageDatabase.java:1654)
> at org.apache.kahadb.page.Transaction.execute(Transaction.java:769)
> at org.apache.activemq.store.kahadb.MessageDatabase$StoredDestinationMarshaller.readPayload(MessageDatabase.java:1642)
> at org.apache.activemq.store.kahadb.MessageDatabase$StoredDestinationMarshaller.readPayload(MessageDatabase.java:1627)
> at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTreeNode.java:201)
> at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTreeNode.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:262)
> at org.apache.kahadb.index.BTreeIndex.getRoot(BTreeIndex.java:174)
> at org.apache.kahadb.index.BTreeIndex.iterator(BTreeIndex.java:228)
> at org.apache.activemq.store.kahadb.KahaDBStore$6.execute(KahaDBStore.java:943)
> at org.apache.kahadb.page.Transaction.execute(Transaction.java:769)
> at org.apache.activemq.store.kahadb.KahaDBStore.getDestinations(KahaDBStore.java:941)
> at org.apache.activemq.store.kahadb.KahaDBPersistenceAdapter.getDestinations(KahaDBPersistenceAdapter.java:122)
> at org.apache.activemq.broker.region.DestinationFactoryImpl.getDestinations(DestinationFactoryImpl.java:68)
> at org.apache.activemq.broker.BrokerService.startVirtualConsumerDestinations(BrokerService.java:2369)
> at org.apache.activemq.broker.BrokerService.startDestinations(BrokerService.java:2198)
> at org.apache.activemq.broker.BrokerService.start(BrokerService.java:527)
> at org.apache.activemq.xbean.XBeanBrokerService.afterPropertiesSet(XBeanBrokerService.java:60)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> at java.lang.reflect.Method.invoke(Method.java:597)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeCustomInitMethod(AbstractAutowireCapableBeanFactory.java:1544)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1485)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1417)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:519)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:456)
> at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:293)
> at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.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.DefaultListableBeanFactory.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.<init>(ResourceXmlApplicationContext.java:64)
> at org.apache.xbean.spring.context.ResourceXmlApplicationContext.<init>(ResourceXmlApplicationContext.java:52)
> at org.apache.activemq.xbean.XBeanBrokerFactory$1.<init>(XBeanBrokerFactory.java:108)
> at org.apache.activemq.xbean.XBeanBrokerFactory.createApplicationContext(XBeanBrokerFactory.java:108)
> at org.apache.activemq.xbean.XBeanBrokerFactory.createBroker(XBeanBrokerFactory.java:72)
> at org.apache.activemq.broker.BrokerFactory.createBroker(BrokerFactory.java:71)
> at org.apache.activemq.broker.BrokerFactory.createBroker(BrokerFactory.java:54)
> at org.apache.activemq.console.command.StartCommand.startBroker(StartCommand.java:115)
> at org.apache.activemq.console.command.StartCommand.runTask(StartCommand.java:74)
> at org.apache.activemq.console.command.AbstractCommand.execute(AbstractCommand.java:57)
> at org.apache.activemq.console.command.ShellCommand.runTask(ShellCommand.java:148)
> at org.apache.activemq.console.command.AbstractCommand.execute(AbstractCommand.java:57)
> at org.apache.activemq.console.command.ShellCommand.main(ShellCommand.java:90)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.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, null) 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.activemq.broker.TransportConnector | main
> 2012-05-29 20:55:36,897 | INFO | PListStore:[/opt/activemq/data/localhost/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
> 2012-05-29 20:55:36,897 | INFO | Stopped KahaDB | org.apache.activemq.store.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 [activemq.xml], reason: Error creating bean with name 'org.apache.activemq.xbean.XBeanBrokerService#0' defined in class path resource [activemq.xml]: Invoc
> ation of init method failed; nested exception is java.lang.NegativeArraySizeException | org.apache.activemq.xbean.XBeanBrokerFactory | main
> org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'org.apache.activemq.xbean.XBeanBrokerService#0' defined in class path resource [activemq.xml]: Invocation of init method failed; nested e
> xception is java.lang.NegativeArraySizeException
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1420)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:519)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:456)
> at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:293)
> at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.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.DefaultListableBeanFactory.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.<init>(ResourceXmlApplicationContext.java:64)
> at org.apache.xbean.spring.context.ResourceXmlApplicationContext.<init>(ResourceXmlApplicationContext.java:52)
> at org.apache.activemq.xbean.XBeanBrokerFactory$1.<init>(XBeanBrokerFactory.java:108)
> at org.apache.activemq.xbean.XBeanBrokerFactory.createApplicationContext(XBeanBrokerFactory.java:108)
> at org.apache.activemq.xbean.XBeanBrokerFactory.createBroker(XBeanBrokerFactory.java:72)
> at org.apache.activemq.broker.BrokerFactory.createBroker(BrokerFactory.java:71)
> at org.apache.activemq.broker.BrokerFactory.createBroker(BrokerFactory.java:54)
> at org.apache.activemq.console.command.StartCommand.startBroker(StartCommand.java:115)
> at org.apache.activemq.console.command.StartCommand.runTask(StartCommand.java:74)
> at org.apache.activemq.console.command.AbstractCommand.execute(AbstractCommand.java:57)
> at org.apache.activemq.console.command.ShellCommand.runTask(ShellCommand.java:148)
> at org.apache.activemq.console.command.AbstractCommand.execute(AbstractCommand.java:57)
> at org.apache.activemq.console.command.ShellCommand.main(ShellCommand.java:90)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.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(BTreeNode.java:188)
> at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTreeNode.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:262)
> at org.apache.kahadb.index.BTreeIndex.getRoot(BTreeIndex.java:174)
> at org.apache.kahadb.index.BTreeIndex.iterator(BTreeIndex.java:228)
> at org.apache.activemq.store.kahadb.MessageDatabase$StoredDestinationMarshaller$1.execute(MessageDatabase.java:1654)
> at org.apache.kahadb.page.Transaction.execute(Transaction.java:769)
> at org.apache.activemq.store.kahadb.MessageDatabase$StoredDestinationMarshaller.readPayload(MessageDatabase.java:1642)
> at org.apache.activemq.store.kahadb.MessageDatabase$StoredDestinationMarshaller.readPayload(MessageDatabase.java:1627)
> at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTreeNode.java:201)
> at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTreeNode.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:262)
> at org.apache.kahadb.index.BTreeIndex.getRoot(BTreeIndex.java:174)
> at org.apache.kahadb.index.BTreeIndex.iterator(BTreeIndex.java:228)
> at org.apache.activemq.store.kahadb.KahaDBStore$6.execute(KahaDBStore.java:943)
> at org.apache.kahadb.page.Transaction.execute(Transaction.java:769)
> at org.apache.activemq.store.kahadb.KahaDBStore.getDestinations(KahaDBStore.java:941)
> at org.apache.activemq.store.kahadb.KahaDBPersistenceAdapter.getDestinations(KahaDBPersistenceAdapter.java:122)
> at org.apache.activemq.broker.region.DestinationFactoryImpl.getDestinations(DestinationFactoryImpl.java:68)
> at org.apache.activemq.broker.BrokerService.startVirtualConsumerDestinations(BrokerService.java:2369)
> at org.apache.activemq.broker.BrokerService.startDestinations(BrokerService.java:2198)
> at org.apache.activemq.broker.BrokerService.start(BrokerService.java:527)
> at org.apache.activemq.xbean.XBeanBrokerService.afterPropertiesSet(XBeanBrokerService.java:60)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> at java.lang.reflect.Method.invoke(Method.java:597)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeCustomInitMethod(AbstractAutowireCapableBeanFactory.java:1544)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1485)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1417)
> ... 28 more
> 11) after 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.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 21:58:01,396 | INFO | Recovering from the journal ... | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 21:58:27,601 | INFO | @2207:10939359, 100000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 21:58:42,788 | INFO | @2222:10328575, 200000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 21:58:59,234 | INFO | @2242:14360209, 300000 entries recovered .. | 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 recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 21:59:43,739 | INFO | @2281:28756842, 600000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:00:13,389 | INFO | @2320:26490711, 700000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:00:47,350 | INFO | @2371:21837918, 800000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:01:17,752 | INFO | @2412:10702462, 900000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:01:51,288 | INFO | @2465:32070937, 1000000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:02:25,203 | INFO | @2519:21797589, 1100000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:02:55,188 | INFO | @2564:13289299, 1200000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:03:05,786 | INFO | @2572:23712519, 1300000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:03:15,375 | INFO | @2578:22618226, 1400000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:03:27,246 | INFO | @2585:31399538, 1500000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:03:38,213 | INFO | @2593:7102179, 1600000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:03:48,285 | INFO | @2600:11040885, 1700000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:03:55,053 | INFO | @2602:28573821, 1800000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:04:01,331 | INFO | @2603:32850602, 1900000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:04:06,689 | INFO | @2605:3582539, 2000000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:04:12,435 | INFO | @2606:7920235, 2100000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:04:17,500 | INFO | @2607:12248010, 2200000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:04:25,521 | INFO | @2617:28414362, 2300000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:04:28,459 | INFO | Recovery replayed 2326036 operations from the journal in 387.094 seconds. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 12) unfortunately, I confirmed that even after upgrade, kahadb continues 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 debugging spun up we see A LOT (I can’t get a count because log files rotate too fast, but in the 6 logs that remain I get 31,978 entries) of the following:
> 2012-05-29 23:18:41,925 | DEBUG | message not found in sequence id index: ID:<FQDN>-59596-1337475432262-0:35:1:1:1202 | org.apache.activemq.store.kahadb.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 administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (AMQ-3866) kahadb log files not getting cleaned
up
Posted by "Alexander Vallens (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/AMQ-3866?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13291108#comment-13291108 ]
Alexander Vallens commented on AMQ-3866:
----------------------------------------
Has anyone seen this bug? If it's invalid, please let us know.
> 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 messages were posted to a queue and slowly consumed over several days until accidentally purged. Ever since then our kahadb has been growing on the order of 12-20 bytes/10 seconds, corresponding to additional entries being added to the kahadb log files that are not being cleaned up (this is even the case in an isolated test environment with no subscribers/consumers/activity). Having searched and found AMQ-3131, AMQ-3736, AMQ-3424, we attempted an upgrade 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) I cloned our ActiveMQ virtual machine “hot” (i.e. without shutdown) and was able to get an isolated (different hostname, IP, VLAN), but functioning, “copy” of the production ActiveMQ instance
> 2) startup 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.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 20:05:28,352 | WARN | Duplicate message add attempt rejected. Destination: Consumer.SchedulerEvents.VirtualTopic.scheduler/events, Message id: ID:<FQDN>-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, Message id: ID:<FQDN>-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, Message id: ID:<FQDN>-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 from the journal in 382.795 seconds. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 3) I was able to eliminate the 3 “duplicate message” warnings by purging the “Consumer.SchedulerEvents.VirtualTopic.scheduler/events” queue (I suspect there were unconsumed messages, perhaps partially uploaded, in that queue at time of clone)
> 4) after the above steps, I was able to observe that kahadb continued to grow at the same rate as the actual production ActiveMQ instancw, ~12-20 bytes every 10s
> 5) during the first normal shutdown of activemq, I observed the following 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$KahaDBMessageStore.resetBatching(KahaDBStore.java:510)
> at org.apache.activemq.store.ProxyMessageStore.resetBatching(ProxyMessageStore.java:93)
> at org.apache.activemq.broker.region.cursors.QueueStorePrefetch.resetBatch(QueueStorePrefetch.java:85)
> at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.stop(AbstractStoreCursor.java:67)
> at org.apache.activemq.broker.region.cursors.StoreQueueCursor.stop(StoreQueueCursor.java:84)
> at org.apache.activemq.broker.region.Queue.stop(Queue.java:872)
> at org.apache.activemq.broker.region.AbstractRegion.stop(AbstractRegion.java:110)
> at org.apache.activemq.util.ServiceStopper.stop(ServiceStopper.java:41)
> at org.apache.activemq.broker.region.RegionBroker.doStop(RegionBroker.java:729)
> at org.apache.activemq.broker.jmx.ManagedRegionBroker.doStop(ManagedRegionBroker.java:113)
> at org.apache.activemq.broker.region.RegionBroker.stop(RegionBroker.java:213)
> at org.apache.activemq.broker.BrokerFilter.stop(BrokerFilter.java:161)
> at org.apache.activemq.broker.scheduler.SchedulerBroker.stop(SchedulerBroker.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(TransactionBroker.java:114)
> at org.apache.activemq.broker.BrokerService$3.stop(BrokerService.java:1795)
> at org.apache.activemq.util.ServiceStopper.stop(ServiceStopper.java:41)
> at org.apache.activemq.broker.BrokerService.stop(BrokerService.java:587)
> at org.apache.activemq.console.command.StartCommand$1.run(StartCommand.java:135)
> 2012-05-29 20:22:09,112 | ERROR | Failed to reset batching | org.apache.activemq.store.kahadb.KahaDBStore | Thread-45
> 6) subsequent shutdowns, however, operated normally without error
> 7) even after various attempts at shutdown and start back up, the aforementioned journal recovery was time consuming:
> 2012-05-29 20:25:06,780 | INFO | Recovering from the journal ... | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 20:31:39,821 | INFO | Recovery replayed 2325954 operations from the journal in 393.074 seconds. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 8) and the kahadb growth issue persisted
> 9) I went ahead and successfully upgraded to ActiveMQ v5.6.0 (verified queues & messages in scheduled queue survived upgrade)
> 10) first attempt to start activemq after 5.6.0 upgrade included following errors:
> 2012-05-29 20:55:36,825 | ERROR | Failed to start ActiveMQ JMS Message Broker (localhost, null). Reason: java.lang.NegativeArraySizeException | org.apache.activemq.broker.BrokerService | main
> java.lang.NegativeArraySizeException
> at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTreeNode.java:188)
> at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTreeNode.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:262)
> at org.apache.kahadb.index.BTreeIndex.getRoot(BTreeIndex.java:174)
> at org.apache.kahadb.index.BTreeIndex.iterator(BTreeIndex.java:228)
> at org.apache.activemq.store.kahadb.MessageDatabase$StoredDestinationMarshaller$1.execute(MessageDatabase.java:1654)
> at org.apache.kahadb.page.Transaction.execute(Transaction.java:769)
> at org.apache.activemq.store.kahadb.MessageDatabase$StoredDestinationMarshaller.readPayload(MessageDatabase.java:1642)
> at org.apache.activemq.store.kahadb.MessageDatabase$StoredDestinationMarshaller.readPayload(MessageDatabase.java:1627)
> at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTreeNode.java:201)
> at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTreeNode.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:262)
> at org.apache.kahadb.index.BTreeIndex.getRoot(BTreeIndex.java:174)
> at org.apache.kahadb.index.BTreeIndex.iterator(BTreeIndex.java:228)
> at org.apache.activemq.store.kahadb.KahaDBStore$6.execute(KahaDBStore.java:943)
> at org.apache.kahadb.page.Transaction.execute(Transaction.java:769)
> at org.apache.activemq.store.kahadb.KahaDBStore.getDestinations(KahaDBStore.java:941)
> at org.apache.activemq.store.kahadb.KahaDBPersistenceAdapter.getDestinations(KahaDBPersistenceAdapter.java:122)
> at org.apache.activemq.broker.region.DestinationFactoryImpl.getDestinations(DestinationFactoryImpl.java:68)
> at org.apache.activemq.broker.BrokerService.startVirtualConsumerDestinations(BrokerService.java:2369)
> at org.apache.activemq.broker.BrokerService.startDestinations(BrokerService.java:2198)
> at org.apache.activemq.broker.BrokerService.start(BrokerService.java:527)
> at org.apache.activemq.xbean.XBeanBrokerService.afterPropertiesSet(XBeanBrokerService.java:60)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> at java.lang.reflect.Method.invoke(Method.java:597)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeCustomInitMethod(AbstractAutowireCapableBeanFactory.java:1544)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1485)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1417)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:519)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:456)
> at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:293)
> at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.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.DefaultListableBeanFactory.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.<init>(ResourceXmlApplicationContext.java:64)
> at org.apache.xbean.spring.context.ResourceXmlApplicationContext.<init>(ResourceXmlApplicationContext.java:52)
> at org.apache.activemq.xbean.XBeanBrokerFactory$1.<init>(XBeanBrokerFactory.java:108)
> at org.apache.activemq.xbean.XBeanBrokerFactory.createApplicationContext(XBeanBrokerFactory.java:108)
> at org.apache.activemq.xbean.XBeanBrokerFactory.createBroker(XBeanBrokerFactory.java:72)
> at org.apache.activemq.broker.BrokerFactory.createBroker(BrokerFactory.java:71)
> at org.apache.activemq.broker.BrokerFactory.createBroker(BrokerFactory.java:54)
> at org.apache.activemq.console.command.StartCommand.startBroker(StartCommand.java:115)
> at org.apache.activemq.console.command.StartCommand.runTask(StartCommand.java:74)
> at org.apache.activemq.console.command.AbstractCommand.execute(AbstractCommand.java:57)
> at org.apache.activemq.console.command.ShellCommand.runTask(ShellCommand.java:148)
> at org.apache.activemq.console.command.AbstractCommand.execute(AbstractCommand.java:57)
> at org.apache.activemq.console.command.ShellCommand.main(ShellCommand.java:90)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.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, null) 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.activemq.broker.TransportConnector | main
> 2012-05-29 20:55:36,897 | INFO | PListStore:[/opt/activemq/data/localhost/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
> 2012-05-29 20:55:36,897 | INFO | Stopped KahaDB | org.apache.activemq.store.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 [activemq.xml], reason: Error creating bean with name 'org.apache.activemq.xbean.XBeanBrokerService#0' defined in class path resource [activemq.xml]: Invoc
> ation of init method failed; nested exception is java.lang.NegativeArraySizeException | org.apache.activemq.xbean.XBeanBrokerFactory | main
> org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'org.apache.activemq.xbean.XBeanBrokerService#0' defined in class path resource [activemq.xml]: Invocation of init method failed; nested e
> xception is java.lang.NegativeArraySizeException
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1420)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:519)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:456)
> at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:293)
> at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.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.DefaultListableBeanFactory.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.<init>(ResourceXmlApplicationContext.java:64)
> at org.apache.xbean.spring.context.ResourceXmlApplicationContext.<init>(ResourceXmlApplicationContext.java:52)
> at org.apache.activemq.xbean.XBeanBrokerFactory$1.<init>(XBeanBrokerFactory.java:108)
> at org.apache.activemq.xbean.XBeanBrokerFactory.createApplicationContext(XBeanBrokerFactory.java:108)
> at org.apache.activemq.xbean.XBeanBrokerFactory.createBroker(XBeanBrokerFactory.java:72)
> at org.apache.activemq.broker.BrokerFactory.createBroker(BrokerFactory.java:71)
> at org.apache.activemq.broker.BrokerFactory.createBroker(BrokerFactory.java:54)
> at org.apache.activemq.console.command.StartCommand.startBroker(StartCommand.java:115)
> at org.apache.activemq.console.command.StartCommand.runTask(StartCommand.java:74)
> at org.apache.activemq.console.command.AbstractCommand.execute(AbstractCommand.java:57)
> at org.apache.activemq.console.command.ShellCommand.runTask(ShellCommand.java:148)
> at org.apache.activemq.console.command.AbstractCommand.execute(AbstractCommand.java:57)
> at org.apache.activemq.console.command.ShellCommand.main(ShellCommand.java:90)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.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(BTreeNode.java:188)
> at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTreeNode.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:262)
> at org.apache.kahadb.index.BTreeIndex.getRoot(BTreeIndex.java:174)
> at org.apache.kahadb.index.BTreeIndex.iterator(BTreeIndex.java:228)
> at org.apache.activemq.store.kahadb.MessageDatabase$StoredDestinationMarshaller$1.execute(MessageDatabase.java:1654)
> at org.apache.kahadb.page.Transaction.execute(Transaction.java:769)
> at org.apache.activemq.store.kahadb.MessageDatabase$StoredDestinationMarshaller.readPayload(MessageDatabase.java:1642)
> at org.apache.activemq.store.kahadb.MessageDatabase$StoredDestinationMarshaller.readPayload(MessageDatabase.java:1627)
> at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTreeNode.java:201)
> at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTreeNode.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:262)
> at org.apache.kahadb.index.BTreeIndex.getRoot(BTreeIndex.java:174)
> at org.apache.kahadb.index.BTreeIndex.iterator(BTreeIndex.java:228)
> at org.apache.activemq.store.kahadb.KahaDBStore$6.execute(KahaDBStore.java:943)
> at org.apache.kahadb.page.Transaction.execute(Transaction.java:769)
> at org.apache.activemq.store.kahadb.KahaDBStore.getDestinations(KahaDBStore.java:941)
> at org.apache.activemq.store.kahadb.KahaDBPersistenceAdapter.getDestinations(KahaDBPersistenceAdapter.java:122)
> at org.apache.activemq.broker.region.DestinationFactoryImpl.getDestinations(DestinationFactoryImpl.java:68)
> at org.apache.activemq.broker.BrokerService.startVirtualConsumerDestinations(BrokerService.java:2369)
> at org.apache.activemq.broker.BrokerService.startDestinations(BrokerService.java:2198)
> at org.apache.activemq.broker.BrokerService.start(BrokerService.java:527)
> at org.apache.activemq.xbean.XBeanBrokerService.afterPropertiesSet(XBeanBrokerService.java:60)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> at java.lang.reflect.Method.invoke(Method.java:597)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeCustomInitMethod(AbstractAutowireCapableBeanFactory.java:1544)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1485)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1417)
> ... 28 more
> 11) after 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.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 21:58:01,396 | INFO | Recovering from the journal ... | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 21:58:27,601 | INFO | @2207:10939359, 100000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 21:58:42,788 | INFO | @2222:10328575, 200000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 21:58:59,234 | INFO | @2242:14360209, 300000 entries recovered .. | 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 recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 21:59:43,739 | INFO | @2281:28756842, 600000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:00:13,389 | INFO | @2320:26490711, 700000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:00:47,350 | INFO | @2371:21837918, 800000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:01:17,752 | INFO | @2412:10702462, 900000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:01:51,288 | INFO | @2465:32070937, 1000000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:02:25,203 | INFO | @2519:21797589, 1100000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:02:55,188 | INFO | @2564:13289299, 1200000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:03:05,786 | INFO | @2572:23712519, 1300000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:03:15,375 | INFO | @2578:22618226, 1400000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:03:27,246 | INFO | @2585:31399538, 1500000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:03:38,213 | INFO | @2593:7102179, 1600000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:03:48,285 | INFO | @2600:11040885, 1700000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:03:55,053 | INFO | @2602:28573821, 1800000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:04:01,331 | INFO | @2603:32850602, 1900000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:04:06,689 | INFO | @2605:3582539, 2000000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:04:12,435 | INFO | @2606:7920235, 2100000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:04:17,500 | INFO | @2607:12248010, 2200000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:04:25,521 | INFO | @2617:28414362, 2300000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:04:28,459 | INFO | Recovery replayed 2326036 operations from the journal in 387.094 seconds. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 12) unfortunately, I confirmed that even after upgrade, kahadb continues 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 debugging spun up we see A LOT (I can’t get a count because log files rotate too fast, but in the 6 logs that remain I get 31,978 entries) of the following:
> 2012-05-29 23:18:41,925 | DEBUG | message not found in sequence id index: ID:<FQDN>-59596-1337475432262-0:35:1:1:1202 | org.apache.activemq.store.kahadb.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 administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (AMQ-3866) kahadb log files not getting cleaned
up
Posted by "Alexander Vallens (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/AMQ-3866?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13295287#comment-13295287 ]
Alexander Vallens commented on AMQ-3866:
----------------------------------------
Gary, thank you for the response.
I went ahead and performed the steps as you outlined. Unfortunately, no change appears to have taken place. After restarting activemq (logging as previously recorded above), the following was logged:
2012-06-14 19:05:08,601 | INFO | @2617:4563875, 2300000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
2012-06-14 19:05:14,527 | INFO | Recovery replayed 2342899 operations from the journal in 412.541 seconds. | org.apache.activemq.store.kahadb.MessageDatabase | main
2012-06-14 19:05:14,606 | DEBUG | Checkpoint started. | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal Checkpoint Worker
2012-06-14 19:05:14,729 | INFO | ActiveMQ 5.6.0 JMS Message Broker (localhost) is starting | org.apache.activemq.broker.BrokerService | main
2012-06-14 19:05:14,729 | INFO | For help or more information please see: http://activemq.apache.org/ | org.apache.activemq.broker.BrokerService | main
2012-06-14 19:05:14,798 | DEBUG | Checkpoint done. | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal Checkpoint Worker
2012-06-14 19:05:14,896 | INFO | Scheduler using directory: /opt/activemq/data/localhost/scheduler | org.apache.activemq.broker.scheduler.SchedulerBroker | main
2012-06-14 19:05:15,299 | DEBUG | Checkpoint started. | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal Checkpoint Worker
2012-06-14 19:05:15,324 | TRACE | Last update: 2627:11845840, full gc candidates set: [2163, 2164, 2165, 2166, 2167, 2168, 2169, 2170, 2171, 2172, 2173, 2174, 2175, 2176, 2177, 2178, 2179, 2180, 2181, 2182, 2183, 2184, 2185, 2186, 2187, 2188, 2189, 2190, 2191, 2192, 2193, 2194, 2195, 2196, 2197, 2198, 2199, 2200, 2201, 2202, 2203, 2204, 2205, 2206, 2207, 2208, 2209, 2210, 2211, 2212, 2213, 2214, 2215, 2216, 2217, 2218, 2219, 2220, 2221, 2222, 2223, 2224, 2225, 2226, 2227, 2228, 2229, 2230, 2231, 2232, 2233, 2234, 2235, 2236, 2237, 2238, 2239, 2240, 2241, 2242, 2243, 2244, 2245, 2246, 2247, 2248, 2249, 2250, 2251, 2252, 2253, 2254, 2255, 2256, 2257, 2258, 2259, 2260, 2261, 2262, 2263, 2264, 2265, 2266, 2267, 2268, 2269, 2270, 2271, 2272, 2273, 2274, 2275, 2276, 2277, 2278, 2279, 2280, 2281, 2282, 2283, 2284, 2285, 2286, 2287, 2288, 2289, 2290, 2291, 2292, 2293, 2294, 2295, 2296, 2297, 2298, 2299, 2300, 2301, 2302, 2303, 2304, 2305, 2306, 2307, 2308, 2309, 2310, 2311, 2312, 2313, 2314, 2315, 2316, 2317, 2318, 2319, 2320, 2321, 2322, 2323, 2324, 2325, 2326, 2327, 2328, 2329, 2330, 2331, 2332, 2333, 2334, 2335, 2336, 2337, 2338, 2339, 2340, 2341, 2342, 2343, 2344, 2345, 2346, 2347, 2348, 2349, 2350, 2351, 2352, 2353, 2354, 2355, 2356, 2357, 2358, 2359, 2360, 2361, 2362, 2363, 2364, 2365, 2366, 2367, 2368, 2369, 2370, 2371, 2372, 2373, 2374, 2375, 2376, 2377, 2378, 2379, 2380, 2381, 2382, 2383, 2384, 2385, 2386, 2387, 2388, 2389, 2390, 2391, 2392, 2393, 2394, 2395, 2396, 2397, 2398, 2399, 2400, 2401, 2402, 2403, 2404, 2405, 2406, 2407, 2408, 2409, 2410, 2411, 2412, 2413, 2414, 2415, 2416, 2417, 2418, 2419, 2420, 2421, 2422, 2423, 2424, 2425, 2426, 2427, 2428, 2429, 2430, 2431, 2432, 2433, 2434, 2435, 2436, 2437, 2438, 2439, 2440, 2441, 2442, 2443, 2444, 2445, 2446, 2447, 2448, 2449, 2450, 2451, 2452, 2453, 2454, 2455, 2456, 2457, 2458, 2459, 2460, 2461, 2462, 2463, 2464, 2465, 2466, 2467, 2468, 2469, 2470, 2471, 2472, 2473, 2474, 2475, 2476, 2477, 2478, 2479, 2480, 2481, 2482, 2483, 2484, 2485, 2486, 2487, 2488, 2489, 2490, 2491, 2492, 2493, 2494, 2495, 2496, 2497, 2498, 2499, 2500, 2501, 2502, 2503, 2504, 2505, 2506, 2507, 2508, 2509, 2510, 2511, 2512, 2513, 2514, 2515, 2516, 2517, 2518, 2519, 2520, 2521, 2522, 2523, 2524, 2525, 2526, 2527, 2528, 2529, 2530, 2531, 2532, 2533, 2534, 2535, 2536, 2537, 2538, 2539, 2540, 2541, 2542, 2543, 2544, 2545, 2546, 2547, 2548, 2549, 2550, 2551, 2552, 2553, 2554, 2555, 2556, 2557, 2558, 2559, 2560, 2561, 2562, 2563, 2564, 2565, 2566, 2567, 2568, 2569, 2570, 2571, 2572, 2573, 2574, 2575, 2576, 2577, 2578, 2579, 2580, 2581, 2582, 2583, 2584, 2585, 2586, 2587, 2588, 2589, 2590, 2591, 2592, 2593, 2594, 2595, 2596, 2597, 2598, 2599, 2600, 2601, 2602, 2603, 2604, 2605, 2606, 2607, 2608, 2609, 2610, 2611, 2612, 2613, 2614, 2615, 2616, 2617, 2618, 2619, 2620, 2621, 2622, 2623, 2624, 2625, 2626, 2627] | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal Checkpoint Worker
2012-06-14 19:05:15,327 | TRACE | gc candidates after first tx:2163:28949756, [] | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal Checkpoint Worker
2012-06-14 19:05:15,327 | TRACE | gc candidates: [] | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal Checkpoint Worker
2012-06-14 19:05:15,327 | DEBUG | Checkpoint done. | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal Checkpoint Worker
2012-06-14 19:05:16,130 | INFO | JobSchedulerStore:/opt/activemq/data/localhost/scheduler started | org.apache.activemq.broker.scheduler.JobSchedulerStore | main
2012-06-14 19:05:16,274 | INFO | Listening for connections at: tcp://<FQDN>:61616 | org.apache.activemq.transport.TransportServerThreadSupport | main
2012-06-14 19:05:16,274 | INFO | Connector openwire Started | org.apache.activemq.broker.TransportConnector | main
2012-06-14 19:05:16,312 | INFO | Listening for connections at: stomp://<FQDN>:61613 | org.apache.activemq.transport.TransportServerThreadSupport | main
2012-06-14 19:05:16,313 | INFO | Connector stomp Started | org.apache.activemq.broker.TransportConnector | main
2012-06-14 19:05:16,321 | INFO | ActiveMQ JMS Message Broker (localhost, ID:<FQDN>-41575-1339700302087-0:1) started | org.apache.activemq.broker.BrokerService | main
2012-06-14 19:05:16,527 | INFO | jetty-7.6.1.v20120215 | org.eclipse.jetty.server.Server | main
2012-06-14 19:05:17,132 | INFO | ActiveMQ WebConsole initialized. | org.apache.activemq.web.WebConsoleStarter | main
2012-06-14 19:05:17,133 | INFO | started o.e.j.w.WebAppContext{/admin,file:/opt/apache-activemq-5.6.0/webapps/admin/} | org.eclipse.jetty.server.handler.ContextHandler | main
2012-06-14 19:05:17,285 | INFO | Initializing Spring FrameworkServlet 'dispatcher' | /admin | main
2012-06-14 19:05:17,966 | INFO | ActiveMQ Console at http://0.0.0.0:8161/admin | org.eclipse.jetty.webapp.WebAppContext | main
2012-06-14 19:05:18,021 | INFO | started o.e.j.w.WebAppContext{/demo,file:/opt/apache-activemq-5.6.0/webapps/demo/} | org.eclipse.jetty.server.handler.ContextHandler | main
2012-06-14 19:05:18,037 | INFO | ActiveMQ Web Demos at http://0.0.0.0:8161/demo | org.eclipse.jetty.webapp.WebAppContext | main
2012-06-14 19:05:18,091 | INFO | started o.e.j.w.WebAppContext{/fileserver,file:/opt/apache-activemq-5.6.0/webapps/fileserver/} | org.eclipse.jetty.server.handler.ContextHandler | main
2012-06-14 19:05:18,107 | INFO | RESTful file access application at http://0.0.0.0:8161/fileserver | org.eclipse.jetty.webapp.WebAppContext | main
2012-06-14 19:05:18,168 | INFO | Started SelectChannelConnector@0.0.0.0:8161 | org.eclipse.jetty.server.AbstractConnector | main
2012-06-14 19:05:20,328 | DEBUG | Checkpoint started. | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal Checkpoint Worker
2012-06-14 19:05:20,348 | DEBUG | Checkpoint done. | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal Checkpoint Worker
2012-06-14 19:05:25,349 | DEBUG | Checkpoint started. | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal Checkpoint Worker
2012-06-14 19:05:25,361 | DEBUG | Checkpoint done. | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal Checkpoint Worker
2012-06-14 19:05:30,362 | DEBUG | Checkpoint started. | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal Checkpoint Worker
2012-06-14 19:05:30,384 | DEBUG | Checkpoint done. | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal Checkpoint Worker
2012-06-14 19:05:35,386 | DEBUG | Checkpoint started. | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal Checkpoint Worker
2012-06-14 19:05:35,386 | DEBUG | Checkpoint started. | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal Checkpoint Worker
2012-06-14 19:05:35,395 | DEBUG | Checkpoint done. | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal Checkpoint Worker
2012-06-14 19:05:40,397 | DEBUG | Checkpoint started. | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal Checkpoint Worker
2012-06-14 19:05:40,405 | DEBUG | Checkpoint done. | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal Checkpoint Worker
2012-06-14 19:05:45,407 | DEBUG | Checkpoint started. | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal Checkpoint Worker
2012-06-14 19:05:45,418 | TRACE | Last update: 2627:11901496, full gc candidates set: [2163, 2164, 2165, 2166, 2167, 2168, 2169, 2170, 2171, 2172, 2173, 2174, 2175, 2176, 2177, 2178, 2179, 2180, 2181, 2182, 2183, 2184, 2185, 2186, 2187, 2188, 2189, 2190, 2191, 2192, 2193, 2194, 2195, 2196, 2197, 2198, 2199, 2200, 2201, 2202, 2203, 2204, 2205, 2206, 2207, 2208, 2209, 2210, 2211, 2212, 2213, 2214, 2215, 2216, 2217, 2218, 2219, 2220, 2221, 2222, 2223, 2224, 2225, 2226, 2227, 2228, 2229, 2230, 2231, 2232, 2233, 2234, 2235, 2236, 2237, 2238, 2239, 2240, 2241, 2242, 2243, 2244, 2245, 2246, 2247, 2248, 2249, 2250, 2251, 2252, 2253, 2254, 2255, 2256, 2257, 2258, 2259, 2260, 2261, 2262, 2263, 2264, 2265, 2266, 2267, 2268, 2269, 2270, 2271, 2272, 2273, 2274, 2275, 2276, 2277, 2278, 2279, 2280, 2281, 2282, 2283, 2284, 2285, 2286, 2287, 2288, 2289, 2290, 2291, 2292, 2293, 2294, 2295, 2296, 2297, 2298, 2299, 2300, 2301, 2302, 2303, 2304, 2305, 2306, 2307, 2308, 2309, 2310, 2311, 2312, 2313, 2314, 2315, 2316, 2317, 2318, 2319, 2320, 2321, 2322, 2323, 2324, 2325, 2326, 2327, 2328, 2329, 2330, 2331, 2332, 2333, 2334, 2335, 2336, 2337, 2338, 2339, 2340, 2341, 2342, 2343, 2344, 2345, 2346, 2347, 2348, 2349, 2350, 2351, 2352, 2353, 2354, 2355, 2356, 2357, 2358, 2359, 2360, 2361, 2362, 2363, 2364, 2365, 2366, 2367, 2368, 2369, 2370, 2371, 2372, 2373, 2374, 2375, 2376, 2377, 2378, 2379, 2380, 2381, 2382, 2383, 2384, 2385, 2386, 2387, 2388, 2389, 2390, 2391, 2392, 2393, 2394, 2395, 2396, 2397, 2398, 2399, 2400, 2401, 2402, 2403, 2404, 2405, 2406, 2407, 2408, 2409, 2410, 2411, 2412, 2413, 2414, 2415, 2416, 2417, 2418, 2419, 2420, 2421, 2422, 2423, 2424, 2425, 2426, 2427, 2428, 2429, 2430, 2431, 2432, 2433, 2434, 2435, 2436, 2437, 2438, 2439, 2440, 2441, 2442, 2443, 2444, 2445, 2446, 2447, 2448, 2449, 2450, 2451, 2452, 2453, 2454, 2455, 2456, 2457, 2458, 2459, 2460, 2461, 2462, 2463, 2464, 2465, 2466, 2467, 2468, 2469, 2470, 2471, 2472, 2473, 2474, 2475, 2476, 2477, 2478, 2479, 2480, 2481, 2482, 2483, 2484, 2485, 2486, 2487, 2488, 2489, 2490, 2491, 2492, 2493, 2494, 2495, 2496, 2497, 2498, 2499, 2500, 2501, 2502, 2503, 2504, 2505, 2506, 2507, 2508, 2509, 2510, 2511, 2512, 2513, 2514, 2515, 2516, 2517, 2518, 2519, 2520, 2521, 2522, 2523, 2524, 2525, 2526, 2527, 2528, 2529, 2530, 2531, 2532, 2533, 2534, 2535, 2536, 2537, 2538, 2539, 2540, 2541, 2542, 2543, 2544, 2545, 2546, 2547, 2548, 2549, 2550, 2551, 2552, 2553, 2554, 2555, 2556, 2557, 2558, 2559, 2560, 2561, 2562, 2563, 2564, 2565, 2566, 2567, 2568, 2569, 2570, 2571, 2572, 2573, 2574, 2575, 2576, 2577, 2578, 2579, 2580, 2581, 2582, 2583, 2584, 2585, 2586, 2587, 2588, 2589, 2590, 2591, 2592, 2593, 2594, 2595, 2596, 2597, 2598, 2599, 2600, 2601, 2602, 2603, 2604, 2605, 2606, 2607, 2608, 2609, 2610, 2611, 2612, 2613, 2614, 2615, 2616, 2617, 2618, 2619, 2620, 2621, 2622, 2623, 2624, 2625, 2626, 2627] | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal Checkpoint Worker
2012-06-14 19:05:45,420 | TRACE | gc candidates after first tx:2163:28949756, [] | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal Checkpoint Worker
2012-06-14 19:05:45,420 | TRACE | gc candidates: [] | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal Checkpoint Worker
2012-06-14 19:05:45,420 | DEBUG | Checkpoint done. | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal Checkpoint Worker
2012-06-14 19:05:50,421 | DEBUG | Checkpoint started. | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal Checkpoint Worker
2012-06-14 19:05:50,430 | DEBUG | Checkpoint done. | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal Checkpoint Worker
2012-06-14 19:05:55,431 | DEBUG | Checkpoint started. | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal Checkpoint Worker
2012-06-14 19:05:55,440 | DEBUG | Checkpoint done. | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal Checkpoint Worker
2012-06-14 19:06:00,441 | DEBUG | Checkpoint started. | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal Checkpoint Worker
2012-06-14 19:06:00,460 | DEBUG | Checkpoint done. | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal Checkpoint Worker
2012-06-14 19:06:05,461 | DEBUG | Checkpoint started. | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal Checkpoint Worker
2012-06-14 19:06:05,469 | DEBUG | Checkpoint done. | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal Checkpoint Worker
2012-06-14 19:06:10,470 | DEBUG | Checkpoint started. | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal Checkpoint Worker
2012-06-14 19:06:10,483 | DEBUG | Checkpoint done. | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal Checkpoint Worker
2012-06-14 19:06:15,484 | DEBUG | Checkpoint started. | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal Checkpoint Worker
2012-06-14 19:06:15,497 | TRACE | Last update: 2627:11957152, full gc candidates set: [2163, 2164, 2165, 2166, 2167, 2168, 2169, 2170, 2171, 2172, 2173, 2174, 2175, 2176, 2177, 2178, 2179, 2180, 2181, 2182, 2183, 2184, 2185, 2186, 2187, 2188, 2189, 2190, 2191, 2192, 2193, 2194, 2195, 2196, 2197, 2198, 2199, 2200, 2201, 2202, 2203, 2204, 2205, 2206, 2207, 2208, 2209, 2210, 2211, 2212, 2213, 2214, 2215, 2216, 2217, 2218, 2219, 2220, 2221, 2222, 2223, 2224, 2225, 2226, 2227, 2228, 2229, 2230, 2231, 2232, 2233, 2234, 2235, 2236, 2237, 2238, 2239, 2240, 2241, 2242, 2243, 2244, 2245, 2246, 2247, 2248, 2249, 2250, 2251, 2252, 2253, 2254, 2255, 2256, 2257, 2258, 2259, 2260, 2261, 2262, 2263, 2264, 2265, 2266, 2267, 2268, 2269, 2270, 2271, 2272, 2273, 2274, 2275, 2276, 2277, 2278, 2279, 2280, 2281, 2282, 2283, 2284, 2285, 2286, 2287, 2288, 2289, 2290, 2291, 2292, 2293, 2294, 2295, 2296, 2297, 2298, 2299, 2300, 2301, 2302, 2303, 2304, 2305, 2306, 2307, 2308, 2309, 2310, 2311, 2312, 2313, 2314, 2315, 2316, 2317, 2318, 2319, 2320, 2321, 2322, 2323, 2324, 2325, 2326, 2327, 2328, 2329, 2330, 2331, 2332, 2333, 2334, 2335, 2336, 2337, 2338, 2339, 2340, 2341, 2342, 2343, 2344, 2345, 2346, 2347, 2348, 2349, 2350, 2351, 2352, 2353, 2354, 2355, 2356, 2357, 2358, 2359, 2360, 2361, 2362, 2363, 2364, 2365, 2366, 2367, 2368, 2369, 2370, 2371, 2372, 2373, 2374, 2375, 2376, 2377, 2378, 2379, 2380, 2381, 2382, 2383, 2384, 2385, 2386, 2387, 2388, 2389, 2390, 2391, 2392, 2393, 2394, 2395, 2396, 2397, 2398, 2399, 2400, 2401, 2402, 2403, 2404, 2405, 2406, 2407, 2408, 2409, 2410, 2411, 2412, 2413, 2414, 2415, 2416, 2417, 2418, 2419, 2420, 2421, 2422, 2423, 2424, 2425, 2426, 2427, 2428, 2429, 2430, 2431, 2432, 2433, 2434, 2435, 2436, 2437, 2438, 2439, 2440, 2441, 2442, 2443, 2444, 2445, 2446, 2447, 2448, 2449, 2450, 2451, 2452, 2453, 2454, 2455, 2456, 2457, 2458, 2459, 2460, 2461, 2462, 2463, 2464, 2465, 2466, 2467, 2468, 2469, 2470, 2471, 2472, 2473, 2474, 2475, 2476, 2477, 2478, 2479, 2480, 2481, 2482, 2483, 2484, 2485, 2486, 2487, 2488, 2489, 2490, 2491, 2492, 2493, 2494, 2495, 2496, 2497, 2498, 2499, 2500, 2501, 2502, 2503, 2504, 2505, 2506, 2507, 2508, 2509, 2510, 2511, 2512, 2513, 2514, 2515, 2516, 2517, 2518, 2519, 2520, 2521, 2522, 2523, 2524, 2525, 2526, 2527, 2528, 2529, 2530, 2531, 2532, 2533, 2534, 2535, 2536, 2537, 2538, 2539, 2540, 2541, 2542, 2543, 2544, 2545, 2546, 2547, 2548, 2549, 2550, 2551, 2552, 2553, 2554, 2555, 2556, 2557, 2558, 2559, 2560, 2561, 2562, 2563, 2564, 2565, 2566, 2567, 2568, 2569, 2570, 2571, 2572, 2573, 2574, 2575, 2576, 2577, 2578, 2579, 2580, 2581, 2582, 2583, 2584, 2585, 2586, 2587, 2588, 2589, 2590, 2591, 2592, 2593, 2594, 2595, 2596, 2597, 2598, 2599, 2600, 2601, 2602, 2603, 2604, 2605, 2606, 2607, 2608, 2609, 2610, 2611, 2612, 2613, 2614, 2615, 2616, 2617, 2618, 2619, 2620, 2621, 2622, 2623, 2624, 2625, 2626, 2627] | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal Checkpoint Worker
2012-06-14 19:06:15,500 | TRACE | gc candidates after first tx:2163:28949756, [] | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal Checkpoint Worker
2012-06-14 19:06:15,500 | TRACE | gc candidates: [] | org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal Checkpoint Worker
The latter pattern (as seen in 2012-06-14 19:05:45,407 - 2012-06-14 19:06:10,483) repeats over and over indefinitely (this was also the case before attempting the db.data & db.redo rebuild as you suggested). As you might suspect, none of my 465 db-*.log files are being cleaned up, as the gc never seems to occur.
> 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 messages were posted to a queue and slowly consumed over several days until accidentally purged. Ever since then our kahadb has been growing on the order of 12-20 bytes/10 seconds, corresponding to additional entries being added to the kahadb log files that are not being cleaned up (this is even the case in an isolated test environment with no subscribers/consumers/activity). Having searched and found AMQ-3131, AMQ-3736, AMQ-3424, we attempted an upgrade 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) I cloned our ActiveMQ virtual machine “hot” (i.e. without shutdown) and was able to get an isolated (different hostname, IP, VLAN), but functioning, “copy” of the production ActiveMQ instance
> 2) startup 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.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 20:05:28,352 | WARN | Duplicate message add attempt rejected. Destination: Consumer.SchedulerEvents.VirtualTopic.scheduler/events, Message id: ID:<FQDN>-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, Message id: ID:<FQDN>-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, Message id: ID:<FQDN>-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 from the journal in 382.795 seconds. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 3) I was able to eliminate the 3 “duplicate message” warnings by purging the “Consumer.SchedulerEvents.VirtualTopic.scheduler/events” queue (I suspect there were unconsumed messages, perhaps partially uploaded, in that queue at time of clone)
> 4) after the above steps, I was able to observe that kahadb continued to grow at the same rate as the actual production ActiveMQ instancw, ~12-20 bytes every 10s
> 5) during the first normal shutdown of activemq, I observed the following 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$KahaDBMessageStore.resetBatching(KahaDBStore.java:510)
> at org.apache.activemq.store.ProxyMessageStore.resetBatching(ProxyMessageStore.java:93)
> at org.apache.activemq.broker.region.cursors.QueueStorePrefetch.resetBatch(QueueStorePrefetch.java:85)
> at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.stop(AbstractStoreCursor.java:67)
> at org.apache.activemq.broker.region.cursors.StoreQueueCursor.stop(StoreQueueCursor.java:84)
> at org.apache.activemq.broker.region.Queue.stop(Queue.java:872)
> at org.apache.activemq.broker.region.AbstractRegion.stop(AbstractRegion.java:110)
> at org.apache.activemq.util.ServiceStopper.stop(ServiceStopper.java:41)
> at org.apache.activemq.broker.region.RegionBroker.doStop(RegionBroker.java:729)
> at org.apache.activemq.broker.jmx.ManagedRegionBroker.doStop(ManagedRegionBroker.java:113)
> at org.apache.activemq.broker.region.RegionBroker.stop(RegionBroker.java:213)
> at org.apache.activemq.broker.BrokerFilter.stop(BrokerFilter.java:161)
> at org.apache.activemq.broker.scheduler.SchedulerBroker.stop(SchedulerBroker.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(TransactionBroker.java:114)
> at org.apache.activemq.broker.BrokerService$3.stop(BrokerService.java:1795)
> at org.apache.activemq.util.ServiceStopper.stop(ServiceStopper.java:41)
> at org.apache.activemq.broker.BrokerService.stop(BrokerService.java:587)
> at org.apache.activemq.console.command.StartCommand$1.run(StartCommand.java:135)
> 2012-05-29 20:22:09,112 | ERROR | Failed to reset batching | org.apache.activemq.store.kahadb.KahaDBStore | Thread-45
> 6) subsequent shutdowns, however, operated normally without error
> 7) even after various attempts at shutdown and start back up, the aforementioned journal recovery was time consuming:
> 2012-05-29 20:25:06,780 | INFO | Recovering from the journal ... | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 20:31:39,821 | INFO | Recovery replayed 2325954 operations from the journal in 393.074 seconds. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 8) and the kahadb growth issue persisted
> 9) I went ahead and successfully upgraded to ActiveMQ v5.6.0 (verified queues & messages in scheduled queue survived upgrade)
> 10) first attempt to start activemq after 5.6.0 upgrade included following errors:
> 2012-05-29 20:55:36,825 | ERROR | Failed to start ActiveMQ JMS Message Broker (localhost, null). Reason: java.lang.NegativeArraySizeException | org.apache.activemq.broker.BrokerService | main
> java.lang.NegativeArraySizeException
> at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTreeNode.java:188)
> at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTreeNode.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:262)
> at org.apache.kahadb.index.BTreeIndex.getRoot(BTreeIndex.java:174)
> at org.apache.kahadb.index.BTreeIndex.iterator(BTreeIndex.java:228)
> at org.apache.activemq.store.kahadb.MessageDatabase$StoredDestinationMarshaller$1.execute(MessageDatabase.java:1654)
> at org.apache.kahadb.page.Transaction.execute(Transaction.java:769)
> at org.apache.activemq.store.kahadb.MessageDatabase$StoredDestinationMarshaller.readPayload(MessageDatabase.java:1642)
> at org.apache.activemq.store.kahadb.MessageDatabase$StoredDestinationMarshaller.readPayload(MessageDatabase.java:1627)
> at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTreeNode.java:201)
> at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTreeNode.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:262)
> at org.apache.kahadb.index.BTreeIndex.getRoot(BTreeIndex.java:174)
> at org.apache.kahadb.index.BTreeIndex.iterator(BTreeIndex.java:228)
> at org.apache.activemq.store.kahadb.KahaDBStore$6.execute(KahaDBStore.java:943)
> at org.apache.kahadb.page.Transaction.execute(Transaction.java:769)
> at org.apache.activemq.store.kahadb.KahaDBStore.getDestinations(KahaDBStore.java:941)
> at org.apache.activemq.store.kahadb.KahaDBPersistenceAdapter.getDestinations(KahaDBPersistenceAdapter.java:122)
> at org.apache.activemq.broker.region.DestinationFactoryImpl.getDestinations(DestinationFactoryImpl.java:68)
> at org.apache.activemq.broker.BrokerService.startVirtualConsumerDestinations(BrokerService.java:2369)
> at org.apache.activemq.broker.BrokerService.startDestinations(BrokerService.java:2198)
> at org.apache.activemq.broker.BrokerService.start(BrokerService.java:527)
> at org.apache.activemq.xbean.XBeanBrokerService.afterPropertiesSet(XBeanBrokerService.java:60)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> at java.lang.reflect.Method.invoke(Method.java:597)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeCustomInitMethod(AbstractAutowireCapableBeanFactory.java:1544)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1485)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1417)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:519)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:456)
> at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:293)
> at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.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.DefaultListableBeanFactory.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.<init>(ResourceXmlApplicationContext.java:64)
> at org.apache.xbean.spring.context.ResourceXmlApplicationContext.<init>(ResourceXmlApplicationContext.java:52)
> at org.apache.activemq.xbean.XBeanBrokerFactory$1.<init>(XBeanBrokerFactory.java:108)
> at org.apache.activemq.xbean.XBeanBrokerFactory.createApplicationContext(XBeanBrokerFactory.java:108)
> at org.apache.activemq.xbean.XBeanBrokerFactory.createBroker(XBeanBrokerFactory.java:72)
> at org.apache.activemq.broker.BrokerFactory.createBroker(BrokerFactory.java:71)
> at org.apache.activemq.broker.BrokerFactory.createBroker(BrokerFactory.java:54)
> at org.apache.activemq.console.command.StartCommand.startBroker(StartCommand.java:115)
> at org.apache.activemq.console.command.StartCommand.runTask(StartCommand.java:74)
> at org.apache.activemq.console.command.AbstractCommand.execute(AbstractCommand.java:57)
> at org.apache.activemq.console.command.ShellCommand.runTask(ShellCommand.java:148)
> at org.apache.activemq.console.command.AbstractCommand.execute(AbstractCommand.java:57)
> at org.apache.activemq.console.command.ShellCommand.main(ShellCommand.java:90)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.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, null) 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.activemq.broker.TransportConnector | main
> 2012-05-29 20:55:36,897 | INFO | PListStore:[/opt/activemq/data/localhost/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
> 2012-05-29 20:55:36,897 | INFO | Stopped KahaDB | org.apache.activemq.store.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 [activemq.xml], reason: Error creating bean with name 'org.apache.activemq.xbean.XBeanBrokerService#0' defined in class path resource [activemq.xml]: Invoc
> ation of init method failed; nested exception is java.lang.NegativeArraySizeException | org.apache.activemq.xbean.XBeanBrokerFactory | main
> org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'org.apache.activemq.xbean.XBeanBrokerService#0' defined in class path resource [activemq.xml]: Invocation of init method failed; nested e
> xception is java.lang.NegativeArraySizeException
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1420)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:519)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:456)
> at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:293)
> at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.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.DefaultListableBeanFactory.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.<init>(ResourceXmlApplicationContext.java:64)
> at org.apache.xbean.spring.context.ResourceXmlApplicationContext.<init>(ResourceXmlApplicationContext.java:52)
> at org.apache.activemq.xbean.XBeanBrokerFactory$1.<init>(XBeanBrokerFactory.java:108)
> at org.apache.activemq.xbean.XBeanBrokerFactory.createApplicationContext(XBeanBrokerFactory.java:108)
> at org.apache.activemq.xbean.XBeanBrokerFactory.createBroker(XBeanBrokerFactory.java:72)
> at org.apache.activemq.broker.BrokerFactory.createBroker(BrokerFactory.java:71)
> at org.apache.activemq.broker.BrokerFactory.createBroker(BrokerFactory.java:54)
> at org.apache.activemq.console.command.StartCommand.startBroker(StartCommand.java:115)
> at org.apache.activemq.console.command.StartCommand.runTask(StartCommand.java:74)
> at org.apache.activemq.console.command.AbstractCommand.execute(AbstractCommand.java:57)
> at org.apache.activemq.console.command.ShellCommand.runTask(ShellCommand.java:148)
> at org.apache.activemq.console.command.AbstractCommand.execute(AbstractCommand.java:57)
> at org.apache.activemq.console.command.ShellCommand.main(ShellCommand.java:90)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.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(BTreeNode.java:188)
> at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTreeNode.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:262)
> at org.apache.kahadb.index.BTreeIndex.getRoot(BTreeIndex.java:174)
> at org.apache.kahadb.index.BTreeIndex.iterator(BTreeIndex.java:228)
> at org.apache.activemq.store.kahadb.MessageDatabase$StoredDestinationMarshaller$1.execute(MessageDatabase.java:1654)
> at org.apache.kahadb.page.Transaction.execute(Transaction.java:769)
> at org.apache.activemq.store.kahadb.MessageDatabase$StoredDestinationMarshaller.readPayload(MessageDatabase.java:1642)
> at org.apache.activemq.store.kahadb.MessageDatabase$StoredDestinationMarshaller.readPayload(MessageDatabase.java:1627)
> at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTreeNode.java:201)
> at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTreeNode.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:262)
> at org.apache.kahadb.index.BTreeIndex.getRoot(BTreeIndex.java:174)
> at org.apache.kahadb.index.BTreeIndex.iterator(BTreeIndex.java:228)
> at org.apache.activemq.store.kahadb.KahaDBStore$6.execute(KahaDBStore.java:943)
> at org.apache.kahadb.page.Transaction.execute(Transaction.java:769)
> at org.apache.activemq.store.kahadb.KahaDBStore.getDestinations(KahaDBStore.java:941)
> at org.apache.activemq.store.kahadb.KahaDBPersistenceAdapter.getDestinations(KahaDBPersistenceAdapter.java:122)
> at org.apache.activemq.broker.region.DestinationFactoryImpl.getDestinations(DestinationFactoryImpl.java:68)
> at org.apache.activemq.broker.BrokerService.startVirtualConsumerDestinations(BrokerService.java:2369)
> at org.apache.activemq.broker.BrokerService.startDestinations(BrokerService.java:2198)
> at org.apache.activemq.broker.BrokerService.start(BrokerService.java:527)
> at org.apache.activemq.xbean.XBeanBrokerService.afterPropertiesSet(XBeanBrokerService.java:60)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> at java.lang.reflect.Method.invoke(Method.java:597)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeCustomInitMethod(AbstractAutowireCapableBeanFactory.java:1544)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1485)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1417)
> ... 28 more
> 11) after 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.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 21:58:01,396 | INFO | Recovering from the journal ... | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 21:58:27,601 | INFO | @2207:10939359, 100000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 21:58:42,788 | INFO | @2222:10328575, 200000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 21:58:59,234 | INFO | @2242:14360209, 300000 entries recovered .. | 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 recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 21:59:43,739 | INFO | @2281:28756842, 600000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:00:13,389 | INFO | @2320:26490711, 700000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:00:47,350 | INFO | @2371:21837918, 800000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:01:17,752 | INFO | @2412:10702462, 900000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:01:51,288 | INFO | @2465:32070937, 1000000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:02:25,203 | INFO | @2519:21797589, 1100000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:02:55,188 | INFO | @2564:13289299, 1200000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:03:05,786 | INFO | @2572:23712519, 1300000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:03:15,375 | INFO | @2578:22618226, 1400000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:03:27,246 | INFO | @2585:31399538, 1500000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:03:38,213 | INFO | @2593:7102179, 1600000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:03:48,285 | INFO | @2600:11040885, 1700000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:03:55,053 | INFO | @2602:28573821, 1800000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:04:01,331 | INFO | @2603:32850602, 1900000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:04:06,689 | INFO | @2605:3582539, 2000000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:04:12,435 | INFO | @2606:7920235, 2100000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:04:17,500 | INFO | @2607:12248010, 2200000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:04:25,521 | INFO | @2617:28414362, 2300000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:04:28,459 | INFO | Recovery replayed 2326036 operations from the journal in 387.094 seconds. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 12) unfortunately, I confirmed that even after upgrade, kahadb continues 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 debugging spun up we see A LOT (I can’t get a count because log files rotate too fast, but in the 6 logs that remain I get 31,978 entries) of the following:
> 2012-05-29 23:18:41,925 | DEBUG | message not found in sequence id index: ID:<FQDN>-59596-1337475432262-0:35:1:1:1202 | org.apache.activemq.store.kahadb.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 administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (AMQ-3866) kahadb log files not getting cleaned
up
Posted by "Gary Tully (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/AMQ-3866?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13295312#comment-13295312 ]
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 transaction, 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 referencing it.
All entries will filter through:{code}org.apache.activemq.store.kahadb.MessageDatabase#process{code} and you can watch for the location offest==28949756
> 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 messages were posted to a queue and slowly consumed over several days until accidentally purged. Ever since then our kahadb has been growing on the order of 12-20 bytes/10 seconds, corresponding to additional entries being added to the kahadb log files that are not being cleaned up (this is even the case in an isolated test environment with no subscribers/consumers/activity). Having searched and found AMQ-3131, AMQ-3736, AMQ-3424, we attempted an upgrade 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) I cloned our ActiveMQ virtual machine “hot” (i.e. without shutdown) and was able to get an isolated (different hostname, IP, VLAN), but functioning, “copy” of the production ActiveMQ instance
> 2) startup 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.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 20:05:28,352 | WARN | Duplicate message add attempt rejected. Destination: Consumer.SchedulerEvents.VirtualTopic.scheduler/events, Message id: ID:<FQDN>-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, Message id: ID:<FQDN>-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, Message id: ID:<FQDN>-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 from the journal in 382.795 seconds. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 3) I was able to eliminate the 3 “duplicate message” warnings by purging the “Consumer.SchedulerEvents.VirtualTopic.scheduler/events” queue (I suspect there were unconsumed messages, perhaps partially uploaded, in that queue at time of clone)
> 4) after the above steps, I was able to observe that kahadb continued to grow at the same rate as the actual production ActiveMQ instancw, ~12-20 bytes every 10s
> 5) during the first normal shutdown of activemq, I observed the following 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$KahaDBMessageStore.resetBatching(KahaDBStore.java:510)
> at org.apache.activemq.store.ProxyMessageStore.resetBatching(ProxyMessageStore.java:93)
> at org.apache.activemq.broker.region.cursors.QueueStorePrefetch.resetBatch(QueueStorePrefetch.java:85)
> at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.stop(AbstractStoreCursor.java:67)
> at org.apache.activemq.broker.region.cursors.StoreQueueCursor.stop(StoreQueueCursor.java:84)
> at org.apache.activemq.broker.region.Queue.stop(Queue.java:872)
> at org.apache.activemq.broker.region.AbstractRegion.stop(AbstractRegion.java:110)
> at org.apache.activemq.util.ServiceStopper.stop(ServiceStopper.java:41)
> at org.apache.activemq.broker.region.RegionBroker.doStop(RegionBroker.java:729)
> at org.apache.activemq.broker.jmx.ManagedRegionBroker.doStop(ManagedRegionBroker.java:113)
> at org.apache.activemq.broker.region.RegionBroker.stop(RegionBroker.java:213)
> at org.apache.activemq.broker.BrokerFilter.stop(BrokerFilter.java:161)
> at org.apache.activemq.broker.scheduler.SchedulerBroker.stop(SchedulerBroker.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(TransactionBroker.java:114)
> at org.apache.activemq.broker.BrokerService$3.stop(BrokerService.java:1795)
> at org.apache.activemq.util.ServiceStopper.stop(ServiceStopper.java:41)
> at org.apache.activemq.broker.BrokerService.stop(BrokerService.java:587)
> at org.apache.activemq.console.command.StartCommand$1.run(StartCommand.java:135)
> 2012-05-29 20:22:09,112 | ERROR | Failed to reset batching | org.apache.activemq.store.kahadb.KahaDBStore | Thread-45
> 6) subsequent shutdowns, however, operated normally without error
> 7) even after various attempts at shutdown and start back up, the aforementioned journal recovery was time consuming:
> 2012-05-29 20:25:06,780 | INFO | Recovering from the journal ... | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 20:31:39,821 | INFO | Recovery replayed 2325954 operations from the journal in 393.074 seconds. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 8) and the kahadb growth issue persisted
> 9) I went ahead and successfully upgraded to ActiveMQ v5.6.0 (verified queues & messages in scheduled queue survived upgrade)
> 10) first attempt to start activemq after 5.6.0 upgrade included following errors:
> 2012-05-29 20:55:36,825 | ERROR | Failed to start ActiveMQ JMS Message Broker (localhost, null). Reason: java.lang.NegativeArraySizeException | org.apache.activemq.broker.BrokerService | main
> java.lang.NegativeArraySizeException
> at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTreeNode.java:188)
> at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTreeNode.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:262)
> at org.apache.kahadb.index.BTreeIndex.getRoot(BTreeIndex.java:174)
> at org.apache.kahadb.index.BTreeIndex.iterator(BTreeIndex.java:228)
> at org.apache.activemq.store.kahadb.MessageDatabase$StoredDestinationMarshaller$1.execute(MessageDatabase.java:1654)
> at org.apache.kahadb.page.Transaction.execute(Transaction.java:769)
> at org.apache.activemq.store.kahadb.MessageDatabase$StoredDestinationMarshaller.readPayload(MessageDatabase.java:1642)
> at org.apache.activemq.store.kahadb.MessageDatabase$StoredDestinationMarshaller.readPayload(MessageDatabase.java:1627)
> at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTreeNode.java:201)
> at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTreeNode.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:262)
> at org.apache.kahadb.index.BTreeIndex.getRoot(BTreeIndex.java:174)
> at org.apache.kahadb.index.BTreeIndex.iterator(BTreeIndex.java:228)
> at org.apache.activemq.store.kahadb.KahaDBStore$6.execute(KahaDBStore.java:943)
> at org.apache.kahadb.page.Transaction.execute(Transaction.java:769)
> at org.apache.activemq.store.kahadb.KahaDBStore.getDestinations(KahaDBStore.java:941)
> at org.apache.activemq.store.kahadb.KahaDBPersistenceAdapter.getDestinations(KahaDBPersistenceAdapter.java:122)
> at org.apache.activemq.broker.region.DestinationFactoryImpl.getDestinations(DestinationFactoryImpl.java:68)
> at org.apache.activemq.broker.BrokerService.startVirtualConsumerDestinations(BrokerService.java:2369)
> at org.apache.activemq.broker.BrokerService.startDestinations(BrokerService.java:2198)
> at org.apache.activemq.broker.BrokerService.start(BrokerService.java:527)
> at org.apache.activemq.xbean.XBeanBrokerService.afterPropertiesSet(XBeanBrokerService.java:60)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> at java.lang.reflect.Method.invoke(Method.java:597)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeCustomInitMethod(AbstractAutowireCapableBeanFactory.java:1544)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1485)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1417)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:519)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:456)
> at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:293)
> at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.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.DefaultListableBeanFactory.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.<init>(ResourceXmlApplicationContext.java:64)
> at org.apache.xbean.spring.context.ResourceXmlApplicationContext.<init>(ResourceXmlApplicationContext.java:52)
> at org.apache.activemq.xbean.XBeanBrokerFactory$1.<init>(XBeanBrokerFactory.java:108)
> at org.apache.activemq.xbean.XBeanBrokerFactory.createApplicationContext(XBeanBrokerFactory.java:108)
> at org.apache.activemq.xbean.XBeanBrokerFactory.createBroker(XBeanBrokerFactory.java:72)
> at org.apache.activemq.broker.BrokerFactory.createBroker(BrokerFactory.java:71)
> at org.apache.activemq.broker.BrokerFactory.createBroker(BrokerFactory.java:54)
> at org.apache.activemq.console.command.StartCommand.startBroker(StartCommand.java:115)
> at org.apache.activemq.console.command.StartCommand.runTask(StartCommand.java:74)
> at org.apache.activemq.console.command.AbstractCommand.execute(AbstractCommand.java:57)
> at org.apache.activemq.console.command.ShellCommand.runTask(ShellCommand.java:148)
> at org.apache.activemq.console.command.AbstractCommand.execute(AbstractCommand.java:57)
> at org.apache.activemq.console.command.ShellCommand.main(ShellCommand.java:90)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.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, null) 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.activemq.broker.TransportConnector | main
> 2012-05-29 20:55:36,897 | INFO | PListStore:[/opt/activemq/data/localhost/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
> 2012-05-29 20:55:36,897 | INFO | Stopped KahaDB | org.apache.activemq.store.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 [activemq.xml], reason: Error creating bean with name 'org.apache.activemq.xbean.XBeanBrokerService#0' defined in class path resource [activemq.xml]: Invoc
> ation of init method failed; nested exception is java.lang.NegativeArraySizeException | org.apache.activemq.xbean.XBeanBrokerFactory | main
> org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'org.apache.activemq.xbean.XBeanBrokerService#0' defined in class path resource [activemq.xml]: Invocation of init method failed; nested e
> xception is java.lang.NegativeArraySizeException
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1420)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:519)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:456)
> at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:293)
> at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.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.DefaultListableBeanFactory.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.<init>(ResourceXmlApplicationContext.java:64)
> at org.apache.xbean.spring.context.ResourceXmlApplicationContext.<init>(ResourceXmlApplicationContext.java:52)
> at org.apache.activemq.xbean.XBeanBrokerFactory$1.<init>(XBeanBrokerFactory.java:108)
> at org.apache.activemq.xbean.XBeanBrokerFactory.createApplicationContext(XBeanBrokerFactory.java:108)
> at org.apache.activemq.xbean.XBeanBrokerFactory.createBroker(XBeanBrokerFactory.java:72)
> at org.apache.activemq.broker.BrokerFactory.createBroker(BrokerFactory.java:71)
> at org.apache.activemq.broker.BrokerFactory.createBroker(BrokerFactory.java:54)
> at org.apache.activemq.console.command.StartCommand.startBroker(StartCommand.java:115)
> at org.apache.activemq.console.command.StartCommand.runTask(StartCommand.java:74)
> at org.apache.activemq.console.command.AbstractCommand.execute(AbstractCommand.java:57)
> at org.apache.activemq.console.command.ShellCommand.runTask(ShellCommand.java:148)
> at org.apache.activemq.console.command.AbstractCommand.execute(AbstractCommand.java:57)
> at org.apache.activemq.console.command.ShellCommand.main(ShellCommand.java:90)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.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(BTreeNode.java:188)
> at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTreeNode.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:262)
> at org.apache.kahadb.index.BTreeIndex.getRoot(BTreeIndex.java:174)
> at org.apache.kahadb.index.BTreeIndex.iterator(BTreeIndex.java:228)
> at org.apache.activemq.store.kahadb.MessageDatabase$StoredDestinationMarshaller$1.execute(MessageDatabase.java:1654)
> at org.apache.kahadb.page.Transaction.execute(Transaction.java:769)
> at org.apache.activemq.store.kahadb.MessageDatabase$StoredDestinationMarshaller.readPayload(MessageDatabase.java:1642)
> at org.apache.activemq.store.kahadb.MessageDatabase$StoredDestinationMarshaller.readPayload(MessageDatabase.java:1627)
> at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTreeNode.java:201)
> at org.apache.kahadb.index.BTreeNode$Marshaller.readPayload(BTreeNode.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:262)
> at org.apache.kahadb.index.BTreeIndex.getRoot(BTreeIndex.java:174)
> at org.apache.kahadb.index.BTreeIndex.iterator(BTreeIndex.java:228)
> at org.apache.activemq.store.kahadb.KahaDBStore$6.execute(KahaDBStore.java:943)
> at org.apache.kahadb.page.Transaction.execute(Transaction.java:769)
> at org.apache.activemq.store.kahadb.KahaDBStore.getDestinations(KahaDBStore.java:941)
> at org.apache.activemq.store.kahadb.KahaDBPersistenceAdapter.getDestinations(KahaDBPersistenceAdapter.java:122)
> at org.apache.activemq.broker.region.DestinationFactoryImpl.getDestinations(DestinationFactoryImpl.java:68)
> at org.apache.activemq.broker.BrokerService.startVirtualConsumerDestinations(BrokerService.java:2369)
> at org.apache.activemq.broker.BrokerService.startDestinations(BrokerService.java:2198)
> at org.apache.activemq.broker.BrokerService.start(BrokerService.java:527)
> at org.apache.activemq.xbean.XBeanBrokerService.afterPropertiesSet(XBeanBrokerService.java:60)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> at java.lang.reflect.Method.invoke(Method.java:597)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeCustomInitMethod(AbstractAutowireCapableBeanFactory.java:1544)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1485)
> at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1417)
> ... 28 more
> 11) after 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.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 21:58:01,396 | INFO | Recovering from the journal ... | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 21:58:27,601 | INFO | @2207:10939359, 100000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 21:58:42,788 | INFO | @2222:10328575, 200000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 21:58:59,234 | INFO | @2242:14360209, 300000 entries recovered .. | 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 recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 21:59:43,739 | INFO | @2281:28756842, 600000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:00:13,389 | INFO | @2320:26490711, 700000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:00:47,350 | INFO | @2371:21837918, 800000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:01:17,752 | INFO | @2412:10702462, 900000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:01:51,288 | INFO | @2465:32070937, 1000000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:02:25,203 | INFO | @2519:21797589, 1100000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:02:55,188 | INFO | @2564:13289299, 1200000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:03:05,786 | INFO | @2572:23712519, 1300000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:03:15,375 | INFO | @2578:22618226, 1400000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:03:27,246 | INFO | @2585:31399538, 1500000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:03:38,213 | INFO | @2593:7102179, 1600000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:03:48,285 | INFO | @2600:11040885, 1700000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:03:55,053 | INFO | @2602:28573821, 1800000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:04:01,331 | INFO | @2603:32850602, 1900000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:04:06,689 | INFO | @2605:3582539, 2000000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:04:12,435 | INFO | @2606:7920235, 2100000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:04:17,500 | INFO | @2607:12248010, 2200000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:04:25,521 | INFO | @2617:28414362, 2300000 entries recovered .. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 2012-05-29 22:04:28,459 | INFO | Recovery replayed 2326036 operations from the journal in 387.094 seconds. | org.apache.activemq.store.kahadb.MessageDatabase | main
> 12) unfortunately, I confirmed that even after upgrade, kahadb continues 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 debugging spun up we see A LOT (I can’t get a count because log files rotate too fast, but in the 6 logs that remain I get 31,978 entries) of the following:
> 2012-05-29 23:18:41,925 | DEBUG | message not found in sequence id index: ID:<FQDN>-59596-1337475432262-0:35:1:1:1202 | org.apache.activemq.store.kahadb.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 administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira