[AMQ-3637] NullPointerException while loading node from kahadb during vmcursor replay

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 5.5.1
• Fix Version/s: 5.6.0
• Component/s: Broker
• Labels: expiry kahadb recovery ttl vmQueueCursor
• Assignee: Gary Tully
• Reporter: Gary Tully
• Created: 15/Dec/11 17:34
• Updated: 16/Dec/11 10:14
• Resolved: 16/Dec/11 10:14

Description

When the vmQueueCursor is used with persistent messages that have a time to live (ttl) expiry set. If the broker down time exceeds the ttl, on recovery the messages are replayed through the vm cursor and an expiry check is done, leading to the messages getting deleted. This nested kahaDB transaction (to remove the message) can badly effect the iterator traversing the store, leading to missed messages and the NPE below. The recovery processing needs to be batched such that periodic expiry can occur with out nesting transactions.

INFO | Recovery replayed 7784653 operations from the journal in 895.065 seconds.
 INFO | ActiveMQ 5.5.1-fuse-01-11 JMS Message Broker () is starting
 INFO | For help or more information please see: http://activemq.apache.org/
ERROR | Failed to start ActiveMQ JMS Message Broker (). Reason: java.lang.NullPointerException
java.lang.NullPointerException
	at org.apache.kahadb.index.BTreeIndex.loadNode(BTreeIndex.java:264)
	at org.apache.kahadb.index.BTreeNode$BTreeIterator.findNextPage(BTreeNode.java:103)
	at org.apache.kahadb.index.BTreeNode$BTreeIterator.hasNext(BTreeNode.java:121)
	at org.apache.activemq.store.kahadb.MessageDatabase$MessageOrderIndex$MessageOrderIterator.hasNext(MessageDatabase.java:2597)
	at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore$3.execute(KahaDBStore.java:506)
	at org.apache.kahadb.page.Transaction.execute(Transaction.java:760)
	at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore.recover(KahaDBStore.java:502)
	at org.apache.activemq.store.ProxyMessageStore.recover(ProxyMessageStore.java:52)
	at org.apache.activemq.broker.region.Queue.initialize(Queue.java:267)
	at org.apache.activemq.broker.region.DestinationFactoryImpl.createDestination(DestinationFactoryImpl.java:86)
	at org.apache.activemq.broker.region.AbstractRegion.createDestination(AbstractRegion.java:487)
	at org.apache.activemq.broker.region.AbstractRegion.addDestination(AbstractRegion.java:125)
	at org.apache.activemq.broker.region.RegionBroker.addDestination(RegionBroker.java:301)
	at org.apache.activemq.broker.BrokerFilter.addDestination(BrokerFilter.java:145)
	at org.apache.activemq.advisory.AdvisoryBroker.addDestination(AdvisoryBroker.java:145)
	at org.apache.activemq.broker.BrokerFilter.addDestination(BrokerFilter.java:145)
	at org.apache.activemq.broker.BrokerFilter.addDestination(BrokerFilter.java:145)
	at org.apache.activemq.broker.MutableBrokerFilter.addDestination(MutableBrokerFilter.java:151)
	at org.apache.activemq.broker.region.AbstractRegion.start(AbstractRegion.java:97)
	at org.apache.activemq.broker.region.RegionBroker.start(RegionBroker.java:201)
	at org.apache.activemq.broker.BrokerFilter.start(BrokerFilter.java:157)
	at org.apache.activemq.broker.BrokerFilter.start(BrokerFilter.java:157)
	at org.apache.activemq.broker.TransactionBroker.start(TransactionBroker.java:123)
	at org.apache.activemq.broker.BrokerService$3.start(BrokerService.java:1814)
	at org.apache.activemq.broker.BrokerService.start(BrokerService.java:494)
	at ...
 INFO | ActiveMQ Message Broker (null) is shutting down