Details
-
Bug
-
Status: Resolved
-
Major
-
Resolution: Not A Problem
-
5.15.2
-
None
-
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.