You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@activemq.apache.org by "Patrick Monfette (JIRA)" <ji...@apache.org> on 2011/01/20 17:23:43 UTC
[jira] Issue Comment Edited: (AMQ-3120) KahaDB error: "Could not
locate data file"
[ https://issues.apache.org/jira/browse/AMQ-3120?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12984262#action_12984262 ]
Patrick Monfette edited comment on AMQ-3120 at 1/20/11 11:22 AM:
-----------------------------------------------------------------
Hello,
We're experiencing the very same issue and I'm also running ActiveMQ 5.4.2. We also have a high quantity of messages, at least 30,000 messages per hours sometimes much more (2x, 3x) than that. We have a mix of very large (fews megs) and very small (few bytes) messages.
What happens: a kaha db missing log (probably deleted too early by kahadb or something else) then messages start accumulating and my consumers are unable to dequeue them.
This issue is really major, if not blocker. This is new since we upgraded to 5.4.2, we never had this problem before with version 5.3.x. I'm unable to reproduce it and it happens randomly, under heavy load or not.
We're running CentOS 4.6, 32 bits.
I found a temporary work around by adding this parameter to the kahadb config, restarting the broker, wait until all the queued messages are consumed, then removing the parameter and restarting the broker again.
{noformat}
<persistenceAdapter>
<kahaDB directory="${activemq.base}/data/kahadb" ignoreMissingJournalfiles="true"/>
</persistenceAdapter>
{noformat}
When you restart the broker with this configuration you will see this and the normal processing continues:
{noformat}
INFO | jvm 1 | 2011/01/20 10:05:20 | INFO | KahaDB is version 3
INFO | jvm 1 | 2011/01/20 10:05:20 | INFO | Recovering from the journal ...
INFO | jvm 1 | 2011/01/20 10:05:20 | INFO | Recovery replayed 1 operations from the journal in 0.045 seconds.
INFO | jvm 1 | 2011/01/20 10:05:20 | INFO | Some journal files are missing: [4311]
INFO | jvm 1 | 2011/01/20 10:05:20 | INFO | Detected missing/corrupt journal files. Dropped 1 messages from the index in 0.028 seconds.
{noformat}
This workaround allows me to at least not lose all the DB like I had to do until today (delete the kahadb folder and restart).
Here is what starts showing over and over again in the wrapper.log when the issue appears:
{noformat}
INFO | jvm 1 | 2011/01/20 07:31:00 | ERROR | Looking for key 4311 but not found in fileMap: {3944=db-3944.log number = 3944 , length = 33760316, 406
7=db-4067.log number = 4067 , length = 33590177, 3947=db-3947.log number = 3947 , length = 33677680, 3948=db-3948.log number = 3948 , length = 33596726,
4068=db-4068.log number = 4068 , length = 33755827, 4075=db-4075.log number = 4075 , length = 34048968, 4322=db-4322.log number = 4322 , length = 3004262
2, 4076=db-4076.log number = 4076 , length = 33734622, 4320=db-4320.log number = 4320 , length = 33622170, 4321=db-4321.log number = 4321 , length = 3360
7934, 3943=db-3943.log number = 3943 , length = 33897766, 3961=db-3961.log number = 3961 , length = 33715187, 3960=db-3960.log number = 3960 , length = 3
3634841, 4021=db-4021.log number = 4021 , length = 33584217, 4022=db-4022.log number = 4022 , length = 33569989, 4090=db-4090.log number = 4090 , length
= 33555654, 3955=db-3955.log number = 3955 , length = 33566643, 4030=db-4030.log number = 4030 , length = 33700887, 4091=db-4091.log number = 4091 , leng
th = 33928309, 4031=db-4031.log number = 4031 , length = 33554494, 3889=db-3889.log number = 3889 , length = 33664097, 3956=db-3956.log number = 3956 , l
ength = 33621892, 3890=db-3890.log number = 3890 , length = 33590196, 4035=db-4035.log number = 4035 , length = 33653742, 4034=db-4034.log number = 4034
, length = 33852330, 3912=db-3912.log number = 3912 , length = 33554464, 3913=db-3913.log number = 3913 , length = 33587386, 4101=db-4101.log number = 41
01 , length = 34013592, 4039=db-4039.log number = 4039 , length = 34009512, 4100=db-4100.log number = 4100 , length = 33576394, 4038=db-4038.log number =
4038 , length = 33564352, 4102=db-4102.log number = 4102 , length = 33630267, 3908=db-3908.log number = 3908 , length = 33660034, 3909=db-3909.log numbe
r = 3909 , length = 33570972, 4317=db-4317.log number = 4317 , length = 33554634, 4316=db-4316.log number = 4316 , length = 33554832, 4319=db-4319.log nu
mber = 4319 , length = 33560765, 3929=db-3929.log number = 3929 , length = 33773224, 4318=db-4318.log number = 4318 , length = 33606627, 3928=db-3928.log
number = 3928 , length = 33575213, 4313=db-4313.log number = 4313 , length = 33666992, 3935=db-3935.log number = 3935 , length = 33716752, 4312=db-4312.
log number = 4312 , length = 33554827, 3934=db-3934.log number = 3934 , length = 33584253, 4315=db-4315.log number = 4315 , length = 33633620, 4314=db-43
14.log number = 4314 , length = 33676339}
INFO | jvm 1 | 2011/01/20 07:31:00 | ERROR | Failed to fill batch
INFO | jvm 1 | 2011/01/20 07:31:00 | java.io.IOException: Could not locate data file /usr/share/activemq/data/kahadb/db-4311.log
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.kahadb.journal.Journal.getDataFile(Journal.java:345)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.kahadb.journal.Journal.read(Journal.java:592)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.store.kahadb.MessageDatabase.load(MessageDatabase.java:786)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.store.kahadb.KahaDBStore.loadMessage(KahaDBStore.java:956)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore$5.execute(KahaDBStore.java:494)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.kahadb.page.Transaction.execute(Transaction.java:728)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore.recoverNextMessages(KahaDBStore.java:4
85)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.store.ProxyMessageStore.recoverNextMessages(ProxyMessageStore.java:88)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.cursors.QueueStorePrefetch.doFillBatch(QueueStorePrefetch.java:97)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:262)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.reset(AbstractStoreCursor.java:110)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.cursors.StoreQueueCursor.reset(StoreQueueCursor.java:157)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.Queue.doPageIn(Queue.java:1678)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.Queue.pageInMessages(Queue.java:1898)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.Queue.iterate(Queue.java:1425)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:122)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:43)
INFO | jvm 1 | 2011/01/20 07:31:00 | at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
INFO | jvm 1 | 2011/01/20 07:31:00 | at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
INFO | jvm 1 | 2011/01/20 07:31:00 | at java.lang.Thread.run(Thread.java:619)
INFO | jvm 1 | 2011/01/20 07:31:00 | ERROR | Failed to fill batch
INFO | jvm 1 | 2011/01/20 07:31:00 | java.lang.RuntimeException: java.io.IOException: Could not locate data file /usr/share/activemq/data/kahadb/db-
4311.log
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:265)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.reset(AbstractStoreCursor.java:110)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.cursors.StoreQueueCursor.reset(StoreQueueCursor.java:157)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.Queue.doPageIn(Queue.java:1678)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.Queue.pageInMessages(Queue.java:1898)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.Queue.iterate(Queue.java:1425)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:122)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:43)
INFO | jvm 1 | 2011/01/20 07:31:00 | at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
INFO | jvm 1 | 2011/01/20 07:31:00 | at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
INFO | jvm 1 | 2011/01/20 07:31:00 | at java.lang.Thread.run(Thread.java:619)
INFO | jvm 1 | 2011/01/20 07:31:00 | Caused by: java.io.IOException: Could not locate data file /usr/share/activemq/data/kahadb/db-4311.log
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.kahadb.journal.Journal.getDataFile(Journal.java:345)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.kahadb.journal.Journal.read(Journal.java:592)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.store.kahadb.MessageDatabase.load(MessageDatabase.java:786)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.store.kahadb.KahaDBStore.loadMessage(KahaDBStore.java:956)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore$5.execute(KahaDBStore.java:494)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.kahadb.page.Transaction.execute(Transaction.java:728)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore.recoverNextMessages(KahaDBStore.java:4
85)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.store.ProxyMessageStore.recoverNextMessages(ProxyMessageStore.java:88)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.cursors.QueueStorePrefetch.doFillBatch(QueueStorePrefetch.java:97)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:262)
INFO | jvm 1 | 2011/01/20 07:31:00 | ... 10 more
INFO | jvm 1 | 2011/01/20 07:31:00 | ERROR | Failed to page in more queue messages
INFO | jvm 1 | 2011/01/20 07:31:00 | java.lang.RuntimeException: java.lang.RuntimeException: java.io.IOException: Could not locate data file /usr/sh
are/activemq/data/kahadb/db-4311.log
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.reset(AbstractStoreCursor.java:113)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.cursors.StoreQueueCursor.reset(StoreQueueCursor.java:157)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.Queue.doPageIn(Queue.java:1678)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.Queue.pageInMessages(Queue.java:1898)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.Queue.iterate(Queue.java:1425)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:122)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:43)
INFO | jvm 1 | 2011/01/20 07:31:00 | at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
INFO | jvm 1 | 2011/01/20 07:31:00 | at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
INFO | jvm 1 | 2011/01/20 07:31:00 | at java.lang.Thread.run(Thread.java:619)
INFO | jvm 1 | 2011/01/20 07:31:00 | Caused by: java.lang.RuntimeException: java.io.IOException: Could not locate data file /usr/share/activemq/data
/kahadb/db-4311.log
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:265)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.reset(AbstractStoreCursor.java:110)
INFO | jvm 1 | 2011/01/20 07:31:00 | ... 9 more
INFO | jvm 1 | 2011/01/20 07:31:00 | Caused by: java.io.IOException: Could not locate data file /usr/share/activemq/data/kahadb/db-4311.log
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.kahadb.journal.Journal.getDataFile(Journal.java:345)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.kahadb.journal.Journal.read(Journal.java:592)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.store.kahadb.MessageDatabase.load(MessageDatabase.java:786)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.store.kahadb.KahaDBStore.loadMessage(KahaDBStore.java:956)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore$5.execute(KahaDBStore.java:494)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.kahadb.page.Transaction.execute(Transaction.java:728)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore.recoverNextMessages(KahaDBStore.java:4
85)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.store.ProxyMessageStore.recoverNextMessages(ProxyMessageStore.java:88)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.cursors.QueueStorePrefetch.doFillBatch(QueueStorePrefetch.java:97)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:262)
INFO | jvm 1 | 2011/01/20 07:31:00 | ... 10 more
{noformat}
was (Author: redvortex):
Hello,
We're experiencing the very same issue and I'm also running ActiveMQ 5.4.2. We also have a high quantity of messages, at least 30,000 messages per hours sometimes much more (2x, 3x) than that. We have a mix of very large (fews megs) and very small (few bytes) messages.
What happens: a kaha db missing log (probably deleted too early by kahadb or something else) then messages start accumulating and my consumers are unable to dequeue them.
This issue is really major, if not blocker. This is new since we upgraded to 5.4.2, we never had this problem before with version 5.3.x. I'm unable to reproduce it and it happens randomly, under heavy load or not.
I found a temporary work around by adding this parameter to the kahadb config, restarting the broker, wait until all the queued messages are consumed, then removing the parameter and restarting the broker again.
{noformat}
<persistenceAdapter>
<kahaDB directory="${activemq.base}/data/kahadb" ignoreMissingJournalfiles="true"/>
</persistenceAdapter>
{noformat}
When you restart the broker with this configuration you will see this and the normal processing continues:
{noformat}
INFO | jvm 1 | 2011/01/20 10:05:20 | INFO | KahaDB is version 3
INFO | jvm 1 | 2011/01/20 10:05:20 | INFO | Recovering from the journal ...
INFO | jvm 1 | 2011/01/20 10:05:20 | INFO | Recovery replayed 1 operations from the journal in 0.045 seconds.
INFO | jvm 1 | 2011/01/20 10:05:20 | INFO | Some journal files are missing: [4311]
INFO | jvm 1 | 2011/01/20 10:05:20 | INFO | Detected missing/corrupt journal files. Dropped 1 messages from the index in 0.028 seconds.
{noformat}
This workaround allows me to at least not lose all the DB like I had to do until today (delete the kahadb folder and restart).
Here is what starts showing over and over again in the wrapper.log when the issue appears:
{noformat}
INFO | jvm 1 | 2011/01/20 07:31:00 | ERROR | Looking for key 4311 but not found in fileMap: {3944=db-3944.log number = 3944 , length = 33760316, 406
7=db-4067.log number = 4067 , length = 33590177, 3947=db-3947.log number = 3947 , length = 33677680, 3948=db-3948.log number = 3948 , length = 33596726,
4068=db-4068.log number = 4068 , length = 33755827, 4075=db-4075.log number = 4075 , length = 34048968, 4322=db-4322.log number = 4322 , length = 3004262
2, 4076=db-4076.log number = 4076 , length = 33734622, 4320=db-4320.log number = 4320 , length = 33622170, 4321=db-4321.log number = 4321 , length = 3360
7934, 3943=db-3943.log number = 3943 , length = 33897766, 3961=db-3961.log number = 3961 , length = 33715187, 3960=db-3960.log number = 3960 , length = 3
3634841, 4021=db-4021.log number = 4021 , length = 33584217, 4022=db-4022.log number = 4022 , length = 33569989, 4090=db-4090.log number = 4090 , length
= 33555654, 3955=db-3955.log number = 3955 , length = 33566643, 4030=db-4030.log number = 4030 , length = 33700887, 4091=db-4091.log number = 4091 , leng
th = 33928309, 4031=db-4031.log number = 4031 , length = 33554494, 3889=db-3889.log number = 3889 , length = 33664097, 3956=db-3956.log number = 3956 , l
ength = 33621892, 3890=db-3890.log number = 3890 , length = 33590196, 4035=db-4035.log number = 4035 , length = 33653742, 4034=db-4034.log number = 4034
, length = 33852330, 3912=db-3912.log number = 3912 , length = 33554464, 3913=db-3913.log number = 3913 , length = 33587386, 4101=db-4101.log number = 41
01 , length = 34013592, 4039=db-4039.log number = 4039 , length = 34009512, 4100=db-4100.log number = 4100 , length = 33576394, 4038=db-4038.log number =
4038 , length = 33564352, 4102=db-4102.log number = 4102 , length = 33630267, 3908=db-3908.log number = 3908 , length = 33660034, 3909=db-3909.log numbe
r = 3909 , length = 33570972, 4317=db-4317.log number = 4317 , length = 33554634, 4316=db-4316.log number = 4316 , length = 33554832, 4319=db-4319.log nu
mber = 4319 , length = 33560765, 3929=db-3929.log number = 3929 , length = 33773224, 4318=db-4318.log number = 4318 , length = 33606627, 3928=db-3928.log
number = 3928 , length = 33575213, 4313=db-4313.log number = 4313 , length = 33666992, 3935=db-3935.log number = 3935 , length = 33716752, 4312=db-4312.
log number = 4312 , length = 33554827, 3934=db-3934.log number = 3934 , length = 33584253, 4315=db-4315.log number = 4315 , length = 33633620, 4314=db-43
14.log number = 4314 , length = 33676339}
INFO | jvm 1 | 2011/01/20 07:31:00 | ERROR | Failed to fill batch
INFO | jvm 1 | 2011/01/20 07:31:00 | java.io.IOException: Could not locate data file /usr/share/activemq/data/kahadb/db-4311.log
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.kahadb.journal.Journal.getDataFile(Journal.java:345)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.kahadb.journal.Journal.read(Journal.java:592)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.store.kahadb.MessageDatabase.load(MessageDatabase.java:786)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.store.kahadb.KahaDBStore.loadMessage(KahaDBStore.java:956)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore$5.execute(KahaDBStore.java:494)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.kahadb.page.Transaction.execute(Transaction.java:728)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore.recoverNextMessages(KahaDBStore.java:4
85)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.store.ProxyMessageStore.recoverNextMessages(ProxyMessageStore.java:88)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.cursors.QueueStorePrefetch.doFillBatch(QueueStorePrefetch.java:97)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:262)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.reset(AbstractStoreCursor.java:110)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.cursors.StoreQueueCursor.reset(StoreQueueCursor.java:157)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.Queue.doPageIn(Queue.java:1678)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.Queue.pageInMessages(Queue.java:1898)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.Queue.iterate(Queue.java:1425)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:122)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:43)
INFO | jvm 1 | 2011/01/20 07:31:00 | at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
INFO | jvm 1 | 2011/01/20 07:31:00 | at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
INFO | jvm 1 | 2011/01/20 07:31:00 | at java.lang.Thread.run(Thread.java:619)
INFO | jvm 1 | 2011/01/20 07:31:00 | ERROR | Failed to fill batch
INFO | jvm 1 | 2011/01/20 07:31:00 | java.lang.RuntimeException: java.io.IOException: Could not locate data file /usr/share/activemq/data/kahadb/db-
4311.log
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:265)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.reset(AbstractStoreCursor.java:110)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.cursors.StoreQueueCursor.reset(StoreQueueCursor.java:157)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.Queue.doPageIn(Queue.java:1678)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.Queue.pageInMessages(Queue.java:1898)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.Queue.iterate(Queue.java:1425)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:122)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:43)
INFO | jvm 1 | 2011/01/20 07:31:00 | at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
INFO | jvm 1 | 2011/01/20 07:31:00 | at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
INFO | jvm 1 | 2011/01/20 07:31:00 | at java.lang.Thread.run(Thread.java:619)
INFO | jvm 1 | 2011/01/20 07:31:00 | Caused by: java.io.IOException: Could not locate data file /usr/share/activemq/data/kahadb/db-4311.log
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.kahadb.journal.Journal.getDataFile(Journal.java:345)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.kahadb.journal.Journal.read(Journal.java:592)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.store.kahadb.MessageDatabase.load(MessageDatabase.java:786)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.store.kahadb.KahaDBStore.loadMessage(KahaDBStore.java:956)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore$5.execute(KahaDBStore.java:494)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.kahadb.page.Transaction.execute(Transaction.java:728)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore.recoverNextMessages(KahaDBStore.java:4
85)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.store.ProxyMessageStore.recoverNextMessages(ProxyMessageStore.java:88)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.cursors.QueueStorePrefetch.doFillBatch(QueueStorePrefetch.java:97)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:262)
INFO | jvm 1 | 2011/01/20 07:31:00 | ... 10 more
INFO | jvm 1 | 2011/01/20 07:31:00 | ERROR | Failed to page in more queue messages
INFO | jvm 1 | 2011/01/20 07:31:00 | java.lang.RuntimeException: java.lang.RuntimeException: java.io.IOException: Could not locate data file /usr/sh
are/activemq/data/kahadb/db-4311.log
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.reset(AbstractStoreCursor.java:113)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.cursors.StoreQueueCursor.reset(StoreQueueCursor.java:157)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.Queue.doPageIn(Queue.java:1678)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.Queue.pageInMessages(Queue.java:1898)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.Queue.iterate(Queue.java:1425)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:122)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:43)
INFO | jvm 1 | 2011/01/20 07:31:00 | at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
INFO | jvm 1 | 2011/01/20 07:31:00 | at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
INFO | jvm 1 | 2011/01/20 07:31:00 | at java.lang.Thread.run(Thread.java:619)
INFO | jvm 1 | 2011/01/20 07:31:00 | Caused by: java.lang.RuntimeException: java.io.IOException: Could not locate data file /usr/share/activemq/data
/kahadb/db-4311.log
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:265)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.reset(AbstractStoreCursor.java:110)
INFO | jvm 1 | 2011/01/20 07:31:00 | ... 9 more
INFO | jvm 1 | 2011/01/20 07:31:00 | Caused by: java.io.IOException: Could not locate data file /usr/share/activemq/data/kahadb/db-4311.log
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.kahadb.journal.Journal.getDataFile(Journal.java:345)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.kahadb.journal.Journal.read(Journal.java:592)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.store.kahadb.MessageDatabase.load(MessageDatabase.java:786)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.store.kahadb.KahaDBStore.loadMessage(KahaDBStore.java:956)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore$5.execute(KahaDBStore.java:494)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.kahadb.page.Transaction.execute(Transaction.java:728)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore.recoverNextMessages(KahaDBStore.java:4
85)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.store.ProxyMessageStore.recoverNextMessages(ProxyMessageStore.java:88)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.cursors.QueueStorePrefetch.doFillBatch(QueueStorePrefetch.java:97)
INFO | jvm 1 | 2011/01/20 07:31:00 | at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:262)
INFO | jvm 1 | 2011/01/20 07:31:00 | ... 10 more
{noformat}
> KahaDB error: "Could not locate data file"
> ------------------------------------------
>
> Key: AMQ-3120
> URL: https://issues.apache.org/jira/browse/AMQ-3120
> Project: ActiveMQ
> Issue Type: Bug
> Components: Broker
> Affects Versions: 5.4.2
> Environment: linux: CentOS 5.5
> happens on both dual- and quad-cpu boxes, 4gb ram
> java version "1.6.0_21"
> Java(TM) SE Runtime Environment (build 1.6.0_21-b06)
> Java HotSpot(TM) 64-Bit Server VM (build 17.0-b16, mixed mode)
> Reporter: Dan Checkoway
>
> I'm using an embedded broker (version 5.4.2) with persistence enabled. We're pumping hundreds of millions of messages per day through this thing. Every once in a while, all of a sudden the KahaDB directory starts growing uncontrollably, and these errors start spewing out in the log over and over...
> --------------------------
> ERROR; Jan 5, 2011 16:37:57 PM; tid:BrokerService[localhost] Task; AbstractStoreCursor - Failed to fill batch
> java.lang.RuntimeException: java.io.IOException: Could not locate data file /usr/local/embedded/activemq-data/localhost/KahaDB/db-28098.log
> at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:265)
> at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.hasNext(AbstractStoreCursor.java:148)
> at org.apache.activemq.broker.region.cursors.StoreQueueCursor.hasNext(StoreQueueCursor.java:131)
> at org.apache.activemq.broker.region.Queue.doPageIn(Queue.java:1679)
> at org.apache.activemq.broker.region.Queue.pageInMessages(Queue.java:1898)
> at org.apache.activemq.broker.region.Queue.iterate(Queue.java:1425)
> at org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:122)
> at org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:43)
> at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
> at java.lang.Thread.run(Thread.java:619)
> Caused by: java.io.IOException: Could not locate data file /usr/local/embedded/activemq-data/localhost/KahaDB/db-28098.log
> at org.apache.kahadb.journal.Journal.getDataFile(Journal.java:345)
> at org.apache.kahadb.journal.Journal.read(Journal.java:592)
> at org.apache.activemq.store.kahadb.MessageDatabase.load(MessageDatabase.java:786)
> at org.apache.activemq.store.kahadb.KahaDBStore.loadMessage(KahaDBStore.java:956)
> at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore$5.execute(KahaDBStore.java:494)
> at org.apache.kahadb.page.Transaction.execute(Transaction.java:728)
> at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore.recoverNextMessages(KahaDBStore.java:485)
> at org.apache.activemq.store.ProxyMessageStore.recoverNextMessages(ProxyMessageStore.java:88)
> at org.apache.activemq.broker.region.cursors.QueueStorePrefetch.doFillBatch(QueueStorePrefetch.java:97)
> at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:262)
> ... 10 more
> ERROR; Jan 5, 2011 16:37:57 PM; tid:BrokerService[localhost] Task; Queue - Failed to page in more queue messages
> java.lang.RuntimeException: java.lang.RuntimeException: java.io.IOException: Could not locate data file /usr/local/embedded/activemq-data/localhost/KahaDB/db-28098.log
> at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.hasNext(AbstractStoreCursor.java:151)
> at org.apache.activemq.broker.region.cursors.StoreQueueCursor.hasNext(StoreQueueCursor.java:131)
> at org.apache.activemq.broker.region.Queue.doPageIn(Queue.java:1679)
> at org.apache.activemq.broker.region.Queue.pageInMessages(Queue.java:1898)
> at org.apache.activemq.broker.region.Queue.iterate(Queue.java:1425)
> at org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:122)
> at org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:43)
> at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
> at java.lang.Thread.run(Thread.java:619)
> Caused by: java.lang.RuntimeException: java.io.IOException: Could not locate data file /usr/local/embedded/activemq-data/localhost/KahaDB/db-28098.log
> at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:265)
> at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.hasNext(AbstractStoreCursor.java:148)
> ... 9 more
> Caused by: java.io.IOException: Could not locate data file /usr/local/embedded/activemq-data/localhost/KahaDB/db-28098.log
> at org.apache.kahadb.journal.Journal.getDataFile(Journal.java:345)
> at org.apache.kahadb.journal.Journal.read(Journal.java:592)
> at org.apache.activemq.store.kahadb.MessageDatabase.load(MessageDatabase.java:786)
> at org.apache.activemq.store.kahadb.KahaDBStore.loadMessage(KahaDBStore.java:956)
> at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore$5.execute(KahaDBStore.java:494)
> at org.apache.kahadb.page.Transaction.execute(Transaction.java:728)
> at org.apache.activemq.store.kahadb.KahaDBStore$KahaDBMessageStore.recoverNextMessages(KahaDBStore.java:485)
> at org.apache.activemq.store.ProxyMessageStore.recoverNextMessages(ProxyMessageStore.java:88)
> at org.apache.activemq.broker.region.cursors.QueueStorePrefetch.doFillBatch(QueueStorePrefetch.java:97)
> at org.apache.activemq.broker.region.cursors.AbstractStoreCursor.fillBatch(AbstractStoreCursor.java:262)
> ... 10 more
> --------------------------
> It doesn't happen consistently, but it has happened numerous times. The only way to "fix" it is to kill the app, blow away the KahaDB data directory, and restart (ugh).
> Unfortunately this issue is not reproduceable.
> Here's the embedded broker config, fwiw:
> --------------------------
> <broker xmlns="http://activemq.apache.org/schema/core"
> id="embeddedActivemqBroker"
> useJmx="false"
> persistent="true"
> dataDirectory="/usr/local/embedded/activemq-data"
> schedulerSupport="false"
> advisorySupport="false"
> enableStatistics="true">
> <destinationPolicy>
> <policyMap>
> <policyEntries>
> <policyEntry queue=">" producerFlowControl="false" memoryLimit="20mb"/>
> </policyEntries>
> </policyMap>
> </destinationPolicy>
> </broker>
> --------------------------
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.