[AMQ-4118] Index page overflow (when a value does not fit in a page) can lead to duplicate calls to free

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 5.6.0, 5.7.0
• Fix Version/s: 5.8.0
• Component/s: Message Store
• Labels: index kahadb
• Assignee: Gary Tully
• Reporter: Gary Tully
• Created: 19/Oct/12 22:14
• Updated: 04/Jun/13 18:10
• Resolved: 19/Oct/12 22:21

Description

An overflowed chain is release when it is no longer needed, but the new end page was not stored in the cache, the old value as a part page is reused and freed again. boom. Keeping the cache in sync sorts this.
A workaround is to disable the index page cache with a small indexCacheSize.
Durable subs make this more visible, but the failure symptoms vary with usage. A typical scenario is a classcast when the page is reused in the wrong context or a npe when the free page is loaded from disk.
With durable subs with selectors and large backlogs, the sequence set expansion and shrinkage produces values that can overflow easily. This scenario produced a nice test.

Some resultant stack traces that are symptomatic:

2012-10-19 22:25:11,928 [exPageUsage#5-2] - ERROR MessageDatabase                - KahaDB failed to store to Journal
java.io.EOFException: Chunk stream does not exist, page: 1344 is marked free
	at org.apache.kahadb.page.Transaction$2.readPage(Transaction.java:481)
	at org.apache.kahadb.page.Transaction$2.<init>(Transaction.java:458)
	at org.apache.kahadb.page.Transaction.openInputStream(Transaction.java:455)
	at org.apache.kahadb.page.Transaction.load(Transaction.java:431)
	at org.apache.kahadb.page.Transaction.load(Transaction.java:388)
	at org.apache.kahadb.index.BTreeIndex.loadNode(BTreeIndex.java:262)
	at org.apache.kahadb.index.BTreeNode.getChild(BTreeNode.java:225)
	at org.apache.kahadb.index.BTreeNode.getLeafNode(BTreeNode.java:680)
	at org.apache.kahadb.index.BTreeNode.get(BTreeNode.java:562)
	at org.apache.kahadb.index.BTreeIndex.get(BTreeIndex.java:184)
	at org.apache.activemq.store.kahadb.MessageDatabase$MessageOrderIndex.get(MessageDatabase.java:2616)
	at org.apache.activemq.store.kahadb.MessageDatabase.updateIndex(MessageDatabase.java:1210)
	at org.apache.activemq.store.kahadb.MessageDatabase$15.execute(MessageDatabase.java:1002)
	at org.apache.kahadb.page.Transaction.execute(Transaction.java:790)
	at org.apache.activemq.store.kahadb.MessageDatabase.process(MessageDatabase.java:1000)
	at org.apache.activemq.store.kahadb.MessageDatabase$13.visit(MessageDatabase.java:933)
	at org.apache.activemq.store.kahadb.data.KahaRemoveMessageCommand.visit(KahaRemoveMessageCommand.java:220)
	at org.apache.activemq.store.kahadb.MessageDatabase.process(MessageDatabase.java:925)
	at org.apache.activemq.store.kahadb.MessageDatabase.store(MessageDatabase.java:837)
	at org.apache.activemq.store.kahadb.MessageDatabase.store(MessageDatabase.java:819)
	at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBTopicMessageStore.doAcknowledge(KahaDBStore.java:723)
	at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBTopicMessageStore.acknowledge(KahaDBStore.java:706)
	at org.apache.activemq.store.kahadb.KahaDBTransactionStore.acknowledge(KahaDBTransactionStore.java:519)
	at org.apache.activemq.store.kahadb.KahaDBTransactionStore$2.acknowledge(KahaDBTransactionStore.java:222)
	at org.apache.activemq.broker.region.Topic.acknowledge(Topic.java:528)
	at org.apache.activemq.broker.region.DurableTopicSubscription.acknowledge(DurableTopicSubscription.java:279)
	at ..

java.lang.ClassCastException: java.lang.Long cannot be cast to java.lang.String
        at java.lang.String.compareTo(String.java:92)
        at java.util.Arrays.binarySearch0(Arrays.java:2001)
        at java.util.Arrays.binarySearch(Arrays.java:1943)
        at org.apache.kahadb.index.BTreeNode.put(BTreeNode.java:371)
        at org.apache.kahadb.index.BTreeNode.put(BTreeNode.java:369)       
        at org.apache.kahadb.index.BTreeIndex.put(BTreeIndex.java:189)        
at org.apache.activemq.store.kahadb.MessageDatabase$MessageOrderIndex.put(MessageDatabase.java:2592)
        at org.apache.activemq.store.kahadb.MessageDatabase.upadateIndex(MessageDatabase.java:1168)        at org.apache.activemq.store.kahadb.MessageDatabase$AddOpperation.execute(MessageDatabase.java:2082)        at org.apache.activemq.store.kahadb.MessageDatabase$18.execute(MessageDatabase.java:1095)        at org.apache.kahadb.page.Transaction.execute(Transaction.java:768)
        at org.apache.activemq.store.kahadb.MessageDatabase.process(MessageDatabase.java:1092)
        at org.apache.activemq.store.kahadb.MessageDatabase$13.visit(MessageDatabase.java:961)
        at org.apache.activemq.store.kahadb.data.KahaCommitCommand.visit(KahaCommitCommand.java:130)
        at org.apache.activemq.store.kahadb.MessageDatabase.process(MessageDatabase.java:943)
        at org.apache.activemq.store.kahadb.MessageDatabase.store(MessageDatabase.java:855)
        at org.apache.activemq.store.kahadb.KahaDBTransactionStore.commit(KahaDBTransactionStore.java:267)
        at org.apache.activemq.transaction.XATransaction.storeCommit(XATransaction.java:85)
...

java.lang.NullPointerException
        at org.apache.kahadb.index.BTreeIndex.loadNode(BTreeIndex.java:264)
        at org.apache.kahadb.index.BTreeNode.getChild(BTreeNode.java:225)
        at org.apache.kahadb.index.BTreeNode.getLeafNode(BTreeNode.java:676)
        at org.apache.kahadb.index.BTreeNode.put(BTreeNode.java:369)
        at org.apache.kahadb.index.BTreeIndex.put(BTreeIndex.java:189)
        at org.apache.activemq.store.kahadb.MessageDatabase$MessageOrderIndex.put(MessageDatabase.java:2592)
        at org.apache.activemq.store.kahadb.MessageDatabase.upadateIndex(MessageDatabase.java:1168)
        at org.apache.activemq.store.kahadb.MessageDatabase$AddOpperation.execute(MessageDatabase.java:2082)
        at org.apache.activemq.store.kahadb.MessageDatabase$18.execute(MessageDatabase.java:1095)
        at org.apache.kahadb.page.Transaction.execute(Transaction.java:768)
        at org.apache.activemq.store.kahadb.MessageDatabase.process(MessageDatabase.java:1092)
        at org.apache.activemq.store.kahadb.MessageDatabase$13.visit(MessageDatabase.java:961)
        at org.apache.activemq.store.kahadb.data.KahaCommitCommand.visit(KahaCommitCommand.java:130)
        at org.apache.activemq.store.kahadb.MessageDatabase.process(MessageDatabase.java:943)
        at org.apache.activemq.store.kahadb.MessageDatabase.store(MessageDatabase.java:855)
        at org.apache.activemq.store.kahadb.KahaDBTransactionStore.commit(KahaDBTransactionStore.java:267)

Issue Links

• is duplicated by: AMQ-4259 ClassCastException on Durable topic
• relates to: AMQ-3982 Overlapping PList iterators can read wrong data or throw exceptions about chunk streams not existing.
• relates to: AMQ-3906 repeated error message regarding chunk stream logged
• relates to: AMQ-4573 AMQ not starting when using default heart beat