[AMQ-8105] ActiveMQ stopped suddenly due to corrupted KahaDB journal file - ASF JIRA

XML

Word

Printable

JSON

Details

Type: Bug
Status: Resolved
Priority: Major
Resolution: Not A Problem
Affects Version/s: 5.15.2
Fix Version/s: None
Component/s: KahaDB
Labels:
None

Description

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.15.2

OS: CentOS Linux release 7.4.1708 (Core

Cluster: Active Passive (2 nodes)

Persistent storage: KahaDB. KahaDB directory is on NFS shared mount.

 <persistenceAdapter>
  <kahaDB directory="${activemq.data}/kahadb" ignoreMissingJournalfiles="true"/>
</persistenceAdapter>

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

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

Section 2: Deleting data file 67481

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

It's not deleted, it seems. The following journal files were there on the server with zero size:

-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

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.]

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)

Section 4: Stopping broker.

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

Section 5: Then it stopped Broker

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.

This was cleaned in early. See section 1.

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

This file was there on the server. But no contents in that file. See section 3.

Section 7: trying to recover

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

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.

-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

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.

Attachments

Activity

People

Assignee:: Jean-Baptiste Onofré

Reporter:: Arunlal A

Votes:: 0 Vote for this issue

Watchers:: 2 Start watching this issue

Dates

Created:: 21/Dec/20 05:45

Updated:: 05/Jan/21 15:29

Resolved:: 29/Dec/20 06:18