[AMQ-6174] LevelDB gets corrupted when Primary ActiveMQ server is shutdown while messages are queued to it

• Type: Bug
• Status: Closed
• Priority: Critical
• Resolution: Won't Fix
• Affects Version/s: 5.13.0
• Component/s: LevelDB

Environment

Virtual type detected as xen-para.
Last rubix: Mon Feb 1 11:02:37 2016 release: 74867 version: 2.0.7
Installed kernel: 2.6.18-308.0.0.0.1.el5xen x86_64

• Assignee: Unassigned
• Reporter: Sunil Vishwanath
• Created: 18/Feb/16 16:19
• Updated: 06/Feb/17 14:22
• Resolved: 06/Feb/17 14:22

Description

Currently I am testing the following setup:

ActiveMQ 5.13.0 with LevelDB (3 node cluster).
Zookeeper 3.4.6 (3 node cluster).
File system: NFSv3

Started up all 3 Zookeeper nodes. (aamqzk1, aamqzk2 and aamqzk3)
Started up all 5 ActiveMQ nodes. (aamql1, aamql2, aamql3, aamql4 and aamql5)
I started aamql1 first and all others in order. aamql1 is the master and I am able to see all the queue statistics for aamql1 via ActiveMQ Web Console.

I am also watching all 5 AMQ's "application.log" file using "tail -f application.log” command.

The message producer starts sending messages (about 120,000 of them). While the messages are being queued and also being consumed, I stopped the master instance (aamql1). Now aamql2 becomes the master. About 10 seconds later after all the slave aamq reports to the new master, aamql2 throws the following exception and the instance dies. This keeps repeating as it failover to the next instance.
2016-02-17T15:43:48.358885-08:00 aamql2.bus.jetqa1.syseng.tmcs severity=INFO datetime=2016-02-17 15:43:48,354 thread=LevelDB IOException handler. category=org.apache.activemq.util.DefaultIOExceptionHandler Stopping BrokerService[localhost] due to exception, java.io.EOFException: File '/aamql/local/activemq/data/leveldb/0000000038409848.log' offset: 477491777
2016-02-17T15:43:48.370881-08:00 aamql2.bus.jetqa1.syseng.tmcs java.io.EOFException: File '/aamql/local/activemq/data/leveldb/0000000038409848.log' offset: 477491777
2016-02-17T15:43:48.371003-08:00 aamql2.bus.jetqa1.syseng.tmcs at org.apache.activemq.leveldb.RecordLog$LogReader.read(RecordLog.scala:389)
2016-02-17T15:43:48.371082-08:00 aamql2.bus.jetqa1.syseng.tmcs at org.apache.activemq.leveldb.RecordLog$$anonfun$read$2.apply(RecordLog.scala:654)
2016-02-17T15:43:48.371148-08:00 aamql2.bus.jetqa1.syseng.tmcs at org.apache.activemq.leveldb.RecordLog$$anonfun$read$2.apply(RecordLog.scala:654)
2016-02-17T15:43:48.371219-08:00 aamql2.bus.jetqa1.syseng.tmcs at org.apache.activemq.leveldb.RecordLog.get_reader(RecordLog.scala:644)
2016-02-17T15:43:48.371380-08:00 aamql2.bus.jetqa1.syseng.tmcs at org.apache.activemq.leveldb.RecordLog.read(RecordLog.scala:654)
2016-02-17T15:43:48.371454-08:00 aamql2.bus.jetqa1.syseng.tmcs at org.apache.activemq.leveldb.LevelDBClient.getMessage(LevelDBClient.scala:1335)
2016-02-17T15:43:48.371526-08:00 aamql2.bus.jetqa1.syseng.tmcs at org.apache.activemq.leveldb.LevelDBClient$$anonfun$queueCursor$1.apply(LevelDBClient.scala:1274)
2016-02-17T15:43:48.371604-08:00 aamql2.bus.jetqa1.syseng.tmcs at org.apache.activemq.leveldb.LevelDBClient$$anonfun$queueCursor$1.apply(LevelDBClient.scala:1271)
2016-02-17T15:43:48.371675-08:00 aamql2.bus.jetqa1.syseng.tmcs at org.apache.activemq.leveldb.LevelDBClient$$anonfun$collectionCursor$1$$anonfun$apply$mcV$sp$12.apply(LevelDBClient.scala:1359)
2016-02-17T15:43:48.371746-08:00 aamql2.bus.jetqa1.syseng.tmcs at org.apache.activemq.leveldb.LevelDBClient$$anonfun$collectionCursor$1$$anonfun$apply$mcV$sp$12.apply(LevelDBClient.scala:1358)
2016-02-17T15:43:48.371818-08:00 aamql2.bus.jetqa1.syseng.tmcs at org.apache.activemq.leveldb.LevelDBClient$RichDB.check$4(LevelDBClient.scala:323)
2016-02-17T15:43:48.371888-08:00 aamql2.bus.jetqa1.syseng.tmcs at org.apache.activemq.leveldb.LevelDBClient$RichDB.cursorRange(LevelDBClient.scala:325)
2016-02-17T15:43:48.371960-08:00 aamql2.bus.jetqa1.syseng.tmcs at org.apache.activemq.leveldb.LevelDBClient$$anonfun$collectionCursor$1.apply$mcV$sp(LevelDBClient.scala:1358)
2016-02-17T15:43:48.372034-08:00 aamql2.bus.jetqa1.syseng.tmcs at org.apache.activemq.leveldb.LevelDBClient$$anonfun$collectionCursor$1.apply(LevelDBClient.scala:1358)
2016-02-17T15:43:48.372104-08:00 aamql2.bus.jetqa1.syseng.tmcs at org.apache.activemq.leveldb.LevelDBClient$$anonfun$collectionCursor$1.apply(LevelDBClient.scala:1358)
2016-02-17T15:43:48.372175-08:00 aamql2.bus.jetqa1.syseng.tmcs at org.apache.activemq.leveldb.LevelDBClient.usingIndex(LevelDBClient.scala:1038)
2016-02-17T15:43:48.372259-08:00 aamql2.bus.jetqa1.syseng.tmcs at org.apache.activemq.leveldb.LevelDBClient$$anonfun$might_fail_using_index$1.apply(LevelDBClient.scala:1044)
2016-02-17T15:43:48.372334-08:00 aamql2.bus.jetqa1.syseng.tmcs at org.apache.activemq.leveldb.LevelDBClient.might_fail(LevelDBClient.scala:549)
2016-02-17T15:43:48.372406-08:00 aamql2.bus.jetqa1.syseng.tmcs at org.apache.activemq.leveldb.LevelDBClient.might_fail_using_index(LevelDBClient.scala:1044)
2016-02-17T15:43:48.372488-08:00 aamql2.bus.jetqa1.syseng.tmcs at org.apache.activemq.leveldb.LevelDBClient.collectionCursor(LevelDBClient.scala:1357)
2016-02-17T15:43:48.372573-08:00 aamql2.bus.jetqa1.syseng.tmcs at org.apache.activemq.leveldb.LevelDBClient.queueCursor(LevelDBClient.scala:1271)
2016-02-17T15:43:48.372635-08:00 aamql2.bus.jetqa1.syseng.tmcs at org.apache.activemq.leveldb.DBManager.cursorMessages(DBManager.scala:735)
2016-02-17T15:43:48.372705-08:00 aamql2.bus.jetqa1.syseng.tmcs at org.apache.activemq.leveldb.LevelDBStore$LevelDBMessageStore.recoverNextMessages(LevelDBStore.scala:860)
2016-02-17T15:43:48.372774-08:00 aamql2.bus.jetqa1.syseng.tmcs at org.apache.activemq.broker.region.cursors.QueueStorePrefetch.doFillBatch(QueueStorePrefetch.java:120)
2016-02-17T15:43:48.372844-08:00 aamql2.bus.jetqa1.syseng.tmcs at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:406)
2016-02-17T15:43:48.372913-08:00 aamql2.bus.jetqa1.syseng.tmcs at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.reset(AbstractStoreCursor.java:149)
2016-02-17T15:43:48.372990-08:00 aamql2.bus.jetqa1.syseng.tmcs at org.apache.activemq.broker.region.cursors.StoreQueueCursor.reset(StoreQueueCursor.java:169)
2016-02-17T15:43:48.373060-08:00 aamql2.bus.jetqa1.syseng.tmcs at org.apache.activemq.broker.region.Queue.doPageInForDispatch(Queue.java:1938)
2016-02-17T15:43:48.373130-08:00 aamql2.bus.jetqa1.syseng.tmcs at org.apache.activemq.broker.region.Queue.pageInMessages(Queue.java:2149)
2016-02-17T15:43:48.373201-08:00 aamql2.bus.jetqa1.syseng.tmcs at org.apache.activemq.broker.region.Queue.doBrowse(Queue.java:1137)
2016-02-17T15:43:48.373275-08:00 aamql2.bus.jetqa1.syseng.tmcs at org.apache.activemq.broker.region.Queue.expireMessages(Queue.java:917)
2016-02-17T15:43:48.373344-08:00 aamql2.bus.jetqa1.syseng.tmcs at org.apache.activemq.broker.region.Queue.access$100(Queue.java:103)
2016-02-17T15:43:48.373413-08:00 aamql2.bus.jetqa1.syseng.tmcs at org.apache.activemq.broker.region.Queue$2.run(Queue.java:146)
2016-02-17T15:43:48.373484-08:00 aamql2.bus.jetqa1.syseng.tmcs at org.apache.activemq.thread.SchedulerTimerTask.run(SchedulerTimerTask.java:33)
2016-02-17T15:43:48.373553-08:00 aamql2.bus.jetqa1.syseng.tmcs at java.util.TimerThread.mainLoop(Timer.java:555)
2016-02-17T15:43:48.373622-08:00 aamql2.bus.jetqa1.syseng.tmcs at java.util.TimerThread.run(Timer.java:505)