Major Description
On very fast test machines we got predictable FileNotFoundExceptions when a KahaDB data file was to be replaced by its successor.
See this from the log file:
30.10.2012 21:00:56.359 [ActiveMQ Transport: tcp:///192.168.111.128:3134] [ ] master-My-Company-S1-kellner20-vm Message ID:kellner20-vm-3125-1351618296390-23:1:1:2086:1 sent to queue://My-Company.dxm.request.provisionToTS
30.10.2012 21:00:56.359 [BrokerService[master-My-Company-S1-kellner20-vm] Task-197] [ ] My-Company.dxm.request.provisionToTS toPageIn: 1, Inflight: 0, pagedInMessages.size 0, enqueueCount: 2125, dequeueCount: 2124
-------------------------------------------------------------------------------
30.10.2012 21:00:56.390 [ConcurrentQueueStoreAndDispatch] [ ] *** SEVERE ***
Called from org.apache.activemq.store.kahadb.MessageDatabase.store()
KahaDB failed to store to Journal
-------------------------------------------------------------------------------
java.io.FileNotFoundException: activemq-data\master-My-Company-S1-kellner20-vm\KahaDB\db-2.log (The system cannot find the path specified)
at java.io.RandomAccessFile.open(Native Method)
at java.io.RandomAccessFile.<init>(Unknown Source)
at org.apache.kahadb.journal.DataFile.openRandomAccessFile(DataFile.java:70)
at org.apache.kahadb.journal.DataFileAppender.processQueue(DataFileAppender.java:309)
at org.apache.kahadb.journal.DataFileAppender$1.run(DataFileAppender.java:188)
30.10.2012 21:00:56.375 [BrokerService[master-My-Company-S1-kellner20-vm] Task-197] [ ] org.apache.activemq.broker.region.cursors.QueueStorePrefetch@1afd356:My-Company.dxm.request.provisionToTS,batchResetNeeded=false,storeHasMessages=true,size=0,cacheEnabled=true - fillBatch
30.10.2012 21:00:56.421 [ConcurrentQueueStoreAndDispatch] [ ] NOTIFICATION: HighWater of SEVERE exceeded (value=1, highwater=1)!
30.10.2012 21:00:56.437 [ConcurrentQueueStoreAndDispatch] [ ] Stopping the broker due to IO exception, java.io.FileNotFoundException: activemq-data\master-My-Company-S1-kellner20-vm\KahaDB\db-2.log (The system cannot find the path specified)
java.io.FileNotFoundException: activemq-data\master-My-Company-S1-kellner20-vm\KahaDB\db-2.log (The system cannot find the path specified)
at java.io.RandomAccessFile.open(Native Method)
at java.io.RandomAccessFile.<init>(Unknown Source)
at org.apache.kahadb.journal.DataFile.openRandomAccessFile(DataFile.java:70)
at org.apache.kahadb.journal.DataFileAppender.processQueue(DataFileAppender.java:309)
at org.apache.kahadb.journal.DataFileAppender$1.run(DataFileAppender.java:188)
********************
(end of log file quotation)
********************
Having evaluated all possibilities of the failure, we finally patched the following method of the class Journal::
synchronized DataFile rotateWriteFile() {
int nextNum = !dataFiles.isEmpty() ? dataFiles.getTail().getDataFileId().intValue() + 1 : 1;
File file = getFile(nextNum);
DataFile nextWriteFile = new DataFile(file, nextNum, preferedFileLength);
PATCH START try
catch (InterruptedException e)
{ e.printStackTrace(); }PATCH END
// actually allocate the disk space
fileMap.put(nextWriteFile.getDataFileId(), nextWriteFile);
fileByFileMap.put(file, nextWriteFile);
dataFiles.addLast(nextWriteFile);
return nextWriteFile;
}
*************
This helped, the IO Exception never occurred again after this patch.
It seems that the "nextWriteFile"-object was returned, while the allocating of the new Data File wasn't finished yet.
Anyway, it is very strange that we should have detected this problem, and it never occurred earlier - at least no similar bug (???) seems to have been reported. Therefore, a critical examination of possibly deeper causes could be useful.
Best regards,
Matthias Vetter
ATOS, Frankfurt