Arunlal A created AMQ-8105:
------------------------------
Summary: ActiveMQ stopped suddenly due to corrupted KahaDB journal
file
Key: AMQ-8105
URL: https://issues.apache.org/jira/browse/AMQ-8105
Project: ActiveMQ
Issue Type: Bug
Components: KahaDB
Affects Versions: 5.15.2
Reporter: Arunlal A
We recently faced in issue on our production ActiveMQ cluster. The ActiveMQ
process stopped suddenly with "Failed to load message at" KahaDB journal file.
+*Cluster details*+
*ActiveMQ version:* activemq-5.9.1-2.el7.noarch
*OS:* CentOS Linux release 7.4.1708 (Core
*Cluster:* Active Passive (2 nodes)
*Persistent storage:* KahaDB (default configurations). KahaDB directory is on
NFS shared mount.
{code:java}
<persistenceAdapter>
<kahaDB directory="${activemq.data}/kahadb"/>
</persistenceAdapter>{code}
Issue noticed from ActiveMQ log.
* The AMQ process tried to clear the journal log. Cleared.
* The AMQ tried to delete the journal file (3 journals in our case). Seems
it's not deleted.
* AMQ failed, it's trying to load the journal that it deleted.
* Stopped broker.
* Automatically trying to restart/recover and failed.
*Adding the logs here for more details*
*Section 1:* Cleaning journal file 67481Section 1: Cleaning journal file 67481
{code:java}
2020-12-16 22:51:34,759 | DEBUG | Cleanup removing the data files: [67481] |
org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal Checkpoint
Worker2020-12-16 22:51:34,759 | DEBUG | Checkpoint started. |
org.apache.activemq.store.kahadb.MessageDatabase | ActiveMQ Journal Checkpoint
Worker{code}
*Section 2:* Deleting data file 67481
{code:java}
2020-12-16 22:51:35,200 | DEBUG | Deleting data file: db-67481.log number =
67481 , length = 33554432 |
org.apache.activemq.store.kahadb.disk.journal.Journal | ActiveMQ Journal
Checkpoint Worker2020-12-16 22:51:35,202 | DEBUG | Discarded data file:
db-67481.log number = 67481 , length = 33554432 |
org.apache.activemq.store.kahadb.disk.journal.Journal | ActiveMQ Journal
Checkpoint Worker{code}
It's not deleted, it seems. The following journal files were there on the
server with zero size:
{code:java}
-rw-r--r-- 1 nobody nobody 0 Dec 16 08:26 db-67459.log-rw-r--r-- 1
nobody nobody 0 Dec 16 22:26 db-67480.log-rw-r--r-- 1 nobody nobody
0 Dec 16 23:09 db-67481.log{code}
*Section 3:* Error on AMQ. Reason: failed to load journal file 67459. Assuming
that this file also cleaned up as same as in section 1. [The old log were
rotated on the server.]
{code:java}
2020-12-16 22:51:35,342 | ERROR | Failed to load message at: 67459:30059414 |
org.apache.activemq.store.kahadb.KahaDBStore | ActiveMQ Broker[localhost]
Schedulerjava.io.IOException: Unexpected error on journal read at:
67459:30059414 at
org.apache.activemq.util.IOExceptionSupport.create(IOExceptionSupport.java:28)
at
org.apache.activemq.store.kahadb.KahaDBStore.loadMessage(KahaDBStore.java:1260)
at
org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore$4.execute(KahaDBStore.java:594)
at
org.apache.activemq.store.kahadb.disk.page.Transaction.execute(Transaction.java:779)
at
org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore.recoverNextMessages(KahaDBStore.java:583)
at
org.apache.activemq.store.ProxyMessageStore.recoverNextMessages(ProxyMessageStore.java:110)
at
org.apache.activemq.broker.region.cursors.QueueStorePrefetch.doFillBatch(QueueStorePrefetch.java:127)
at
org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:448)
at
org.apache.activemq.broker.region.cursors.AbstractStoreCursor.reset(AbstractStoreCursor.java:168)
at
org.apache.activemq.broker.region.cursors.StoreQueueCursor.reset(StoreQueueCursor.java:169)
at
org.apache.activemq.broker.region.Queue.doPageInForDispatch(Queue.java:1981) at
org.apache.activemq.broker.region.Queue.pageInMessages(Queue.java:2210) at
org.apache.activemq.broker.region.Queue.doBrowse(Queue.java:1155) at
org.apache.activemq.broker.region.Queue.expireMessages(Queue.java:932) at
org.apache.activemq.broker.region.Queue.access$100(Queue.java:106) at
org.apache.activemq.broker.region.Queue$2.run(Queue.java:149) at
org.apache.activemq.thread.SchedulerTimerTask.run(SchedulerTimerTask.java:33)
at java.util.TimerThread.mainLoop(Timer.java:555) at
java.util.TimerThread.run(Timer.java:505)Caused by: java.io.IOException:
Invalid location size: 67459:30059414, size: 1843 at
org.apache.activemq.store.kahadb.disk.journal.DataFileAccessor.readRecord(DataFileAccessor.java:88)
at
org.apache.activemq.store.kahadb.disk.journal.Journal.read(Journal.java:950) at
org.apache.activemq.store.kahadb.MessageDatabase.load(MessageDatabase.java:1151)
at
org.apache.activemq.store.kahadb.KahaDBStore.loadMessage(KahaDBStore.java:1242){code}
*Section 4:* Stopping broker.
{code:java}
2020-12-16 22:51:35,343 | INFO | Stopping BrokerService[localhost] due to
exception, java.io.IOException: Unexpected error on journal read at:
67459:30059414 | org.apache.activemq.util.DefaultIOExceptionHandler | ActiveMQ
Broker[localhost] Schedulerjava.io.IOException: Unexpected error on journal
read at: 67459:30059414
Caused by: java.io.IOException: Invalid location size: 67459:30059414, size:
1843
2020-12-16 22:51:35,345 | ERROR |
org.apache.activemq.broker.region.cursors.QueueStorePrefetch@20307b25:REMINDERS_QUEUE,batchResetNeeded=false,size=46,cacheEnabled=false,maxBatchSize:46,hasSpace:true,pendingCachedIds.size:0,lastSyncCachedId:null,lastSyncCachedId-seq:null,lastAsyncCachedId:null,lastAsyncCachedId-seq:null,store=permits:10000,sd=nextSeq:55349190,lastRet:MessageOrderCursor:[def:0,
low:0, high:0],pending:0 - Failed to fill batch |
org.apache.activemq.broker.region.cursors.AbstractStoreCursor | ActiveMQ
Broker[localhost] Schedulerorg.apache.activemq.broker.SuppressReplyException:
ShutdownBrokerInitiated{code}
*Section 5*: Then it stopped Broker
{code:java}
2020-12-16 22:51:36,548 | DEBUG | stopping
qtp1166106620{STARTED,8<=8<=200,i=8,q=0} |
org.eclipse.jetty.util.component.AbstractLifeCycle | IOExceptionHandler:
stopping BrokerService[localhost]2020-12-16 22:51:36,552 | DEBUG | STOPPED
qtp1166106620{STOPPED,8<=8<=200,i=0,q=0} |
org.eclipse.jetty.util.component.AbstractLifeCycle | IOExceptionHandler:
stopping BrokerService[localhost]2020-12-16 22:51:36,553 | DEBUG | STOPPED
org.eclipse.jetty.server.Server@5e1fa5b1 |
org.eclipse.jetty.util.component.AbstractLifeCycle | IOExceptionHandler:
stopping ````
Section 6: Trying to load KahaDB again - Seems starting AMQ again. Failed at
loading journal 67481.{code}
This was cleaned in early. See section 1.
{code:java}
2020-12-16 22:51:37,577 | DEBUG | loading |
org.apache.activemq.store.kahadb.disk.index.BTreeIndex | main2020-12-16
22:51:37,578 | DEBUG | loading |
org.apache.activemq.store.kahadb.disk.index.ListIndex | main2020-12-16
22:51:37,578 | DEBUG | loading |
org.apache.activemq.store.kahadb.disk.index.ListIndex | main2020-12-16
22:51:37,579 | ERROR | Looking for key 67481 but not found in fileMap:
{67395=db-67395.log number = 67395 , length = 33554432, 67459=db-67459.log
number = 67459 , length = 0, 67397=db-67397.log number = 67397 , length =
33554432, 67461=db-67461.log number = 67461 , length = 33554432,
67463=db-67463.log number = 67463 , length = 33554432, 67465=db-67465.log
number = 67465 , length = 33554432, 67467=db-67467.log number = 67467 , length
= 33554432, 67469=db-67469.log number = 67469 , length = 33554432,
67471=db-67471.log number = 67471 , length = 33554432, 67473=db-67473.log
number = 67473 , length = 33554432, 67411=db-67411.log number = 67411 , length
= 33554432, 67348=db-67348.log number = 67348 , length = 33554432,
67353=db-67353.log number = 67353 , length = 33554432, 67480=db-67480.log
number = 67480 , length = 0, 67354=db-67354.log number = 67354 , length =
33554432, 67482=db-67482.log number = 67482 , length = 627205,
67423=db-67423.log number = 67423 , length = 33554432, 67425=db-67425.log
number = 67425 , length = 33553724, 67363=db-67363.log number = 67363 , length
= 33554432, 67362=db-67362.log number = 67362 , length = 33554432,
67373=db-67373.log number = 67373 , length = 33554432, 54190=db-54190.log
number = 54190 , length = 33554445, 67377=db-67377.log number = 67377 , length
= 33554432, 67376=db-67376.log number = 67376 , length = 33554432,
67317=db-67317.log number = 67317 , length = 33554432, 67380=db-67380.log
number = 67380 , length = 33554432, 67382=db-67382.log number = 67382 , length
= 33554448, 67318=db-67318.log number = 67318 , length = 33554432,
67320=db-67320.log number = 67320 , length = 33554432, 67384=db-67384.log
number = 67384 , length = 33554432, 53946=db-53946.log number = 53946 , length
= 33554432, 67322=db-67322.log number = 67322 , length = 33554432} |
org.apache.activemq.store.kahadb.disk.journal.Journal | main2020-12-16
22:51:37,580 | WARN | Cannot recover message audit |
org.apache.activemq.store.kahadb.MessageDatabase | mainjava.io.IOException:
Could not locate data file /opt/apache-activemq-5.15.2/data/kahadb/db-67481.log
at
org.apache.activemq.store.kahadb.disk.journal.Journal.getDataFile(Journal.java:725)
at org.apache.activemq.store.kahadb.disk.journal.Journal.read(Journal.java:946)
2020-12-16 22:51:38,049 | WARN | Exception encountered during context
initialization - cancelling refresh attempt:
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
exception is java.io.IOException: Could not locate data file
/opt/apache-activemq-5.15.2/data/kahadb/db-67481.log |
org.apache.activemq.xbean.XBeanBrokerFactory$1 | main
{code}
This file was there on the server. But no contents in that file. See section 3.
*Section 7*: trying to recover
{code:java}
2020-12-16 23:21:01,116 | INFO | ignoring zero length, partially initialised
journal data file: db-67459.log number = 67459 , length = 0 |
org.apache.activemq.store.kahadb.disk.journal.Journal | main2020-12-16
23:21:01,116 | INFO | ignoring zero length, partially initialised journal data
file: db-67480.log number = 67480 , length = 0 |
org.apache.activemq.store.kahadb.disk.journal.Journal | main2020-12-16
23:21:01,116 | INFO | ignoring zero length, partially initialised journal data
file: db-67481.log number = 67481 , length = 0 |
org.apache.activemq.store.kahadb.disk.journal.Journal | main2020-12-16
23:21:01,212 | DEBUG | Page File:
/opt/apache-activemq-5.15.2/data/kahadb/db.data, Recovering page file... |
org.apache.activemq.store.kahadb.disk.page.PageFile | main2020-12-16
23:21:14,191 | INFO | KahaDB is version 6 |
org.apache.activemq.store.kahadb.MessageDatabase | main2020-12-16 23:21:14,197
| DEBUG | loading | org.apache.activemq.store.kahadb.disk.index.BTreeIndex |
main2020-12-16 23:21:14,216 | DEBUG | loading |
org.apache.activemq.store.kahadb.disk.index.BTreeIndex |
main.....................................
.........................................
.........................................
................>>>>>>>
2020-12-16 23:21:14,351 | DEBUG | loading |
org.apache.activemq.store.kahadb.disk.index.ListIndex | main2020-12-16
23:21:14,351 | DEBUG | loading |
org.apache.activemq.store.kahadb.disk.index.ListIndex | main2020-12-16
23:21:14,360 | WARN | Cannot recover message audit |
org.apache.activemq.store.kahadb.MessageDatabase | mainjava.io.EOFException at
java.io.RandomAccessFile.readInt(RandomAccessFile.java:803) at
org.apache.activemq.util.RecoverableRandomAccessFile.readInt(RecoverableRandomAccessFile.java:169)
at
org.apache.activemq.store.kahadb.disk.journal.DataFileAccessor.readRecord(DataFileAccessor.java:82)
at
org.apache.activemq.store.kahadb.disk.journal.Journal.read(Journal.java:950) at
org.apache.activemq.store.kahadb.MessageDatabase.load(MessageDatabase.java:1151)
at
org.apache.activemq.store.kahadb.MessageDatabase.recoverProducerAudit(MessageDatabase.java:784)
at
org.apache.activemq.store.kahadb.MessageDatabase.recover(MessageDatabase.java:674)
at
org.apache.activemq.store.kahadb.MessageDatabase.open(MessageDatabase.java:473)
at
org.apache.activemq.store.kahadb.MessageDatabase.load(MessageDatabase.java:493)
at
org.apache.activemq.store.kahadb.MessageDatabase.doStart(MessageDatabase.java:297)
at org.apache.activemq.store.kahadb.KahaDBStore.doStart(KahaDBStore.java:219)
at org.apache.activemq.util.ServiceSupport.start(ServiceSupport.java:55) at
org.apache.activemq.store.kahadb.KahaDBPersistenceAdapter.doStart(KahaDBPersistenceAdapter.java:232)
at org.apache.activemq.util.ServiceSupport.start(ServiceSupport.java:55) at
org.apache.activemq.broker.BrokerService.doStartPersistenceAdapter(BrokerService.java:687)
at
org.apache.activemq.broker.BrokerService.startPersistenceAdapter(BrokerService.java:671)
at org.apache.activemq.broker.BrokerService.start(BrokerService.java:635) at
org.apache.activemq.xbean.XBeanBrokerService.afterPropertiesSet(XBeanBrokerService.java:73)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498) at
org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeCustomInitMethod(AbstractAutowireCapableBeanFactory.java:1758)
at
org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1695)
at
org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1624)
at
org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:555)
at
org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:483)
at
org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:306)
at
org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:230)
at
org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:302)
at
org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:197)
at
org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:761)
at
org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:867)
at
org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:543)
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:104)
at
org.apache.activemq.xbean.XBeanBrokerFactory.createApplicationContext(XBeanBrokerFactory.java:104)
at
org.apache.activemq.xbean.XBeanBrokerFactory.createBroker(XBeanBrokerFactory.java:67)
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.runTask(StartCommand.java:87)
at
org.apache.activemq.console.command.AbstractCommand.execute(AbstractCommand.java:63)
at
org.apache.activemq.console.command.ShellCommand.runTask(ShellCommand.java:154)
at
org.apache.activemq.console.command.AbstractCommand.execute(AbstractCommand.java:63)
at
org.apache.activemq.console.command.ShellCommand.main(ShellCommand.java:104) at
sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498) at
org.apache.activemq.console.Main.runTaskClass(Main.java:262) at
org.apache.activemq.console.Main.main(Main.java:115)
2020-12-16 23:21:14,378 | WARN | Cannot recover ackMessageFileMap |
org.apache.activemq.store.kahadb.MessageDatabase | mainjava.io.EOFException at
java.io.RandomAccessFile.readInt(RandomAccessFile.java:803) at
org.apache.activemq.util.RecoverableRandomAccessFile.readInt(RecoverableRandomAccessFile.java:169)
at
org.apache.activemq.store.kahadb.disk.journal.DataFileAccessor.readRecord(DataFileAccessor.java:82)
at
org.apache.activemq.store.kahadb.disk.journal.Journal.read(Journal.java:950) at
org.apache.activemq.store.kahadb.MessageDatabase.load(MessageDatabase.java:1151)
at
org.apache.activemq.store.kahadb.MessageDatabase.recoverAckMessageFileMap(MessageDatabase.java:805)
at
org.apache.activemq.store.kahadb.MessageDatabase.recover(MessageDatabase.java:675)
at
org.apache.activemq.store.kahadb.MessageDatabase.open(MessageDatabase.java:473)
at
org.apache.activemq.store.kahadb.MessageDatabase.load(MessageDatabase.java:493)
at
org.apache.activemq.store.kahadb.MessageDatabase.doStart(MessageDatabase.java:297)
at org.apache.activemq.store.kahadb.KahaDBStore.doStart(KahaDBStore.java:219)
at org.apache.activemq.util.ServiceSupport.start(ServiceSupport.java:55) at
org.apache.activemq.store.kahadb.KahaDBPersistenceAdapter.doStart(KahaDBPersistenceAdapter.java:232)
at org.apache.activemq.util.ServiceSupport.start(ServiceSupport.java:55) at
org.apache.activemq.broker.BrokerService.doStartPersistenceAdapter(BrokerService.java:687)
at
org.apache.activemq.broker.BrokerService.startPersistenceAdapter(BrokerService.java:671)
at org.apache.activemq.broker.BrokerService.start(BrokerService.java:635) at
org.apache.activemq.xbean.XBeanBrokerService.afterPropertiesSet(XBeanBrokerService.java:73)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498) at
org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeCustomInitMethod(AbstractAutowireCapableBeanFactory.java:1758)
at
org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1695)
at
org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1624)
at
org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:555)
at
org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:483)
at
org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:306)
at
org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:230)
at
org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:302)
at
org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:197)
at
org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:761)
at
org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:867)
at
org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:543)
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:104)
at
org.apache.activemq.xbean.XBeanBrokerFactory.createApplicationContext(XBeanBrokerFactory.java:104)
at
org.apache.activemq.xbean.XBeanBrokerFactory.createBroker(XBeanBrokerFactory.java:67)
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.runTask(StartCommand.java:87)
at
org.apache.activemq.console.command.AbstractCommand.execute(AbstractCommand.java:63)
at
org.apache.activemq.console.command.ShellCommand.runTask(ShellCommand.java:154)
at
org.apache.activemq.console.command.AbstractCommand.execute(AbstractCommand.java:63)
at
org.apache.activemq.console.command.ShellCommand.main(ShellCommand.java:104) at
sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498) at
org.apache.activemq.console.Main.runTaskClass(Main.java:262) at
org.apache.activemq.console.Main.main(Main.java:115)
2020-12-16 23:21:14,381 | ERROR | Failed to start Apache ActiveMQ (localhost,
null) | org.apache.activemq.broker.BrokerService |
mainjava.lang.NullPointerException at
org.apache.activemq.store.kahadb.disk.util.LinkedNode.isTailNode(LinkedNode.java:68)
at
org.apache.activemq.store.kahadb.disk.util.LinkedNode.getNext(LinkedNode.java:48)
at
org.apache.activemq.store.kahadb.disk.journal.Journal.getNextLocation(Journal.java:901)
at
org.apache.activemq.store.kahadb.disk.journal.Journal.getNextLocation(Journal.java:865)
at
org.apache.activemq.store.kahadb.MessageDatabase.getNextInitializedLocation(MessageDatabase.java:1042)
at
org.apache.activemq.store.kahadb.MessageDatabase.getRecoveryPosition(MessageDatabase.java:1034)
at
org.apache.activemq.store.kahadb.MessageDatabase.recover(MessageDatabase.java:676)
at
org.apache.activemq.store.kahadb.MessageDatabase.open(MessageDatabase.java:473)
at
org.apache.activemq.store.kahadb.MessageDatabase.load(MessageDatabase.java:493)
at
org.apache.activemq.store.kahadb.MessageDatabase.doStart(MessageDatabase.java:297)
at org.apache.activemq.store.kahadb.KahaDBStore.doStart(KahaDBStore.java:219)
at org.apache.activemq.util.ServiceSupport.start(ServiceSupport.java:55) at
org.apache.activemq.store.kahadb.KahaDBPersistenceAdapter.doStart(KahaDBPersistenceAdapter.java:232)
at org.apache.activemq.util.ServiceSupport.start(ServiceSupport.java:55) at
org.apache.activemq.broker.BrokerService.doStartPersistenceAdapter(BrokerService.java:687)
at
org.apache.activemq.broker.BrokerService.startPersistenceAdapter(BrokerService.java:671)
at org.apache.activemq.broker.BrokerService.start(BrokerService.java:635) at
org.apache.activemq.xbean.XBeanBrokerService.afterPropertiesSet(XBeanBrokerService.java:73)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498) at
org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeCustomInitMethod(AbstractAutowireCapableBeanFactory.java:1758)
at
org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1695)
at
org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1624)
at
org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:555)
at
org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:483)
at
org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:306)
at
org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:230)
at
org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:302)
at
org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:197)
at
org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:761)
at
org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:867)
at
org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:543)
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:104)
at
org.apache.activemq.xbean.XBeanBrokerFactory.createApplicationContext(XBeanBrokerFactory.java:104)
at
org.apache.activemq.xbean.XBeanBrokerFactory.createBroker(XBeanBrokerFactory.java:67)
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.runTask(StartCommand.java:87)
at
org.apache.activemq.console.command.AbstractCommand.execute(AbstractCommand.java:63)
at
org.apache.activemq.console.command.ShellCommand.runTask(ShellCommand.java:154)
at
org.apache.activemq.console.command.AbstractCommand.execute(AbstractCommand.java:63)
at
org.apache.activemq.console.command.ShellCommand.main(ShellCommand.java:104) at
sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498) at
org.apache.activemq.console.Main.runTaskClass(Main.java:262) at
org.apache.activemq.console.Main.main(Main.java:115)2020-12-16 23:21:14,393 |
INFO | Apache ActiveMQ 5.15.2 (localhost, null) is shutting down |
org.apache.activemq.broker.BrokerService | main{code}
*Section 8:* Repeating same.
To fix we removed the KahaDB directory and recreated and then started the
ActiveMQ process again on both the nodes.
Can someone help me to understand the issue here, please ? Why AMQ were trying
to load message from the journal that already removed. Those journals (3 in our
case) were cleared but not deleted.
{code:java}
-rw-r--r-- 1 nobody nobody 0 Dec 16 08:26 db-67459.log
-rw-r--r-- 1 nobody nobody 0 Dec 16 22:26 db-67480.log
-rw-r--r-- 1 nobody nobody 0 Dec 16 23:09 db-67481.log{code}
*System resources analysis*
* Have done analysis on both AMQ nodes + the NFS cluster (KahaDB data dir is
on NFS mount). Nothing found suspicious there (Prometheus Node Exporter).
* JMX metrics also looks fine. Heap usage was normal. Disk usage was low (1.5
GB). Queue size was also normal.
Is there any bug in this version.
Future plan: We are planning to containerise ActiveMQ with the same version. So
please help me to understand the issue.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
