You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@activemq.apache.org by "Matthias Vetter (JIRA)" <ji...@apache.org> on 2012/11/12 10:54:11 UTC
[jira] [Created] (AMQ-4171) KahaDB / Journal rotateWriteFIle()
sometimes too fast?
Matthias Vetter created AMQ-4171:
------------------------------------
Summary: KahaDB / Journal rotateWriteFIle() sometimes too fast?
Key: AMQ-4171
URL: https://issues.apache.org/jira/browse/AMQ-4171
Project: ActiveMQ
Issue Type: Bug
Components: Broker
Affects Versions: 5.6.0
Environment: Tested on Windows (7)
Reporter: Matthias Vetter
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 {
Thread.sleep(10000);
} 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
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Updated] (AMQ-4171) KahaDB / Journal rotateWriteFIle()
sometimes too fast?
Posted by "Matthias Vetter (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/AMQ-4171?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Matthias Vetter updated AMQ-4171:
---------------------------------
Environment: Tested on Windows XP (was: Tested on Windows (7))
> KahaDB / Journal rotateWriteFIle() sometimes too fast?
> ------------------------------------------------------
>
> Key: AMQ-4171
> URL: https://issues.apache.org/jira/browse/AMQ-4171
> Project: ActiveMQ
> Issue Type: Bug
> Components: Broker
> Affects Versions: 5.6.0
> Environment: Tested on Windows XP
> Reporter: Matthias Vetter
>
> 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 {
> Thread.sleep(10000);
> } 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
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (AMQ-4171) KahaDB / Journal rotateWriteFIle()
sometimes too fast?
Posted by "Matthias Vetter (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/AMQ-4171?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13503146#comment-13503146 ]
Matthias Vetter commented on AMQ-4171:
--------------------------------------
After deeper examination of the above described failure, we still have no solution the problem:
It is always possible to create the first file db-1.log. But the creation of its successor always fails, always with the same exception: file not found, the system cannot find the path specified.
The DataFileAppender gets the next DataFile-object (from the method we suspected to be too fast) and then this DataFile object‘s method openRandomAccessFile is called. At this moment, the physical file is not yet existing, the RandomAccessFile-constructor is supposed to create the file. It did so, when db-1.log was created: The path to the files, naturally, wasn’t changed after that, and the same rights in the file system still are granted.
The only difference we see is, that now another file is already present and is about to be deleted. But should this have such an effect?
We also suspected the whitespaces in the absolute path to the file to be a problem – but why not in the first case?
Even more irritating is that obviously no one else faced such kind of FileNotFound problem.
Finally, the problem seems to occur not on Windows 7, as initially reported, but on Windows XP. It also didn’t occur on a Solaris machine.
Please, has anyone an idea what could be going on here? An comment is welcome!!!!
> KahaDB / Journal rotateWriteFIle() sometimes too fast?
> ------------------------------------------------------
>
> Key: AMQ-4171
> URL: https://issues.apache.org/jira/browse/AMQ-4171
> Project: ActiveMQ
> Issue Type: Bug
> Components: Broker
> Affects Versions: 5.6.0
> Environment: Tested on Windows (7)
> Reporter: Matthias Vetter
>
> 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 {
> Thread.sleep(10000);
> } 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
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Comment Edited] (AMQ-4171) KahaDB / Journal
rotateWriteFIle() sometimes too fast?
Posted by "Matthias Vetter (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/AMQ-4171?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13503146#comment-13503146 ]
Matthias Vetter edited comment on AMQ-4171 at 11/23/12 10:34 AM:
-----------------------------------------------------------------
After deeper examination of the above described failure, we still have no solution to the problem:
It is always possible to create the first file db-1.log. But the creation of its successor always fails, always with the same exception: file not found, the system cannot find the path specified.
The DataFileAppender gets the next DataFile-object (from the method we suspected to be too fast) and then this DataFile object‘s method openRandomAccessFile is called. At this moment, the physical file is not yet existing, the RandomAccessFile-constructor called by the open-method is supposed to create the file. It did so, when db-1.log was created. The path to the files, naturally, wasn’t changed after that, and the same rights in the file system still are granted.
The only difference we see is, that now another file is already present and is about to be deleted. But should this have such an effect?
We also suspected the whitespaces in the absolute path to the file to be a problem – but why not in the first case with db-1.log?
Even more irritating is that obviously no one else faced such kind of FileNotFound problem with the KahaDB.
Finally, the problem seems to occur not on Windows 7, as initially reported, but on Windows XP. It also didn’t occur on a Solaris machine.
Please, has anyone an idea what could be going on here? Any comment is welcome!!!!
was (Author: mtmvetter):
After deeper examination of the above described failure, we still have no solution the problem:
It is always possible to create the first file db-1.log. But the creation of its successor always fails, always with the same exception: file not found, the system cannot find the path specified.
The DataFileAppender gets the next DataFile-object (from the method we suspected to be too fast) and then this DataFile object‘s method openRandomAccessFile is called. At this moment, the physical file is not yet existing, the RandomAccessFile-constructor is supposed to create the file. It did so, when db-1.log was created: The path to the files, naturally, wasn’t changed after that, and the same rights in the file system still are granted.
The only difference we see is, that now another file is already present and is about to be deleted. But should this have such an effect?
We also suspected the whitespaces in the absolute path to the file to be a problem – but why not in the first case?
Even more irritating is that obviously no one else faced such kind of FileNotFound problem.
Finally, the problem seems to occur not on Windows 7, as initially reported, but on Windows XP. It also didn’t occur on a Solaris machine.
Please, has anyone an idea what could be going on here? An comment is welcome!!!!
> KahaDB / Journal rotateWriteFIle() sometimes too fast?
> ------------------------------------------------------
>
> Key: AMQ-4171
> URL: https://issues.apache.org/jira/browse/AMQ-4171
> Project: ActiveMQ
> Issue Type: Bug
> Components: Broker
> Affects Versions: 5.6.0
> Environment: Tested on Windows (7)
> Reporter: Matthias Vetter
>
> 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 {
> Thread.sleep(10000);
> } 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
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Updated] (AMQ-4171) KahaDB / Journal rotateWriteFIle()
sometimes too fast?
Posted by "Matthias Vetter (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/AMQ-4171?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Matthias Vetter updated AMQ-4171:
---------------------------------
Patch Info: (was: Patch Available)
> KahaDB / Journal rotateWriteFIle() sometimes too fast?
> ------------------------------------------------------
>
> Key: AMQ-4171
> URL: https://issues.apache.org/jira/browse/AMQ-4171
> Project: ActiveMQ
> Issue Type: Bug
> Components: Broker
> Affects Versions: 5.6.0
> Environment: Tested on Windows XP
> Reporter: Matthias Vetter
>
> 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 {
> Thread.sleep(10000);
> } 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
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (AMQ-4171) KahaDB / Journal rotateWriteFIle()
sometimes too fast?
Posted by "Matthias Vetter (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/AMQ-4171?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13506465#comment-13506465 ]
Matthias Vetter commented on AMQ-4171:
--------------------------------------
Although it is strange that the file not found behaviour depends on the starting mode, there is a possibility to prevent the exception:
org.apache.kahadb.journal.DataFile.openRandomAccessFile
calls: new RandomAccessFile(file, "rw");. Replacing this by
new RandomAccessFile(file.getCanonicalPath(), "rw"); helped!
Whatever the deeper causes for the problem may be, the kahaDB would gain stability by opening RandomAccessFiles generally with os-proof pathnames rather than with file objects.
> KahaDB / Journal rotateWriteFIle() sometimes too fast?
> ------------------------------------------------------
>
> Key: AMQ-4171
> URL: https://issues.apache.org/jira/browse/AMQ-4171
> Project: ActiveMQ
> Issue Type: Bug
> Components: Broker
> Affects Versions: 5.6.0
> Environment: Tested on Windows XP
> Reporter: Matthias Vetter
>
> 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 {
> Thread.sleep(10000);
> } 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
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (AMQ-4171) KahaDB / Journal rotateWriteFIle()
sometimes too fast?
Posted by "Matthias Vetter (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/AMQ-4171?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13504729#comment-13504729 ]
Matthias Vetter commented on AMQ-4171:
--------------------------------------
In the meantime we found out, that all depends on the way we start our server, in which the broker is embedded. Using Windows (Win7 or xp, JDK 6 or 7 - all this doesn't matter), we can start the server either as a Windows service, using a .ini-file, from which jre/bin/server/jvm.dll is called,
either manually using a .bat-file, calling java.exe. The jvm-parameters we pass are both times the same.
Starting java.exe never leads to the described failures, starting with java.dll always. Needless to say, it stays a riddle how the start methods are related to the fileNotFound problem.
Anyone experienced something like this?
m.v.
> KahaDB / Journal rotateWriteFIle() sometimes too fast?
> ------------------------------------------------------
>
> Key: AMQ-4171
> URL: https://issues.apache.org/jira/browse/AMQ-4171
> Project: ActiveMQ
> Issue Type: Bug
> Components: Broker
> Affects Versions: 5.6.0
> Environment: Tested on Windows XP
> Reporter: Matthias Vetter
>
> 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 {
> Thread.sleep(10000);
> } 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
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (AMQ-4171) KahaDB / Journal rotateWriteFIle()
sometimes too fast?
Posted by "Matthias Vetter (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/AMQ-4171?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13496252#comment-13496252 ]
Matthias Vetter commented on AMQ-4171:
--------------------------------------
Hi Timothy,
you are right, and I am sorry for having created an issue entry too early. Nevertheless, the delay really helped for some time. But today we detected an fileNotFound Exception inspite the delay, eventually.
So we have to keep on searching for the real problem..
Thanks!
Best regards,
Matthias Vetter
> KahaDB / Journal rotateWriteFIle() sometimes too fast?
> ------------------------------------------------------
>
> Key: AMQ-4171
> URL: https://issues.apache.org/jira/browse/AMQ-4171
> Project: ActiveMQ
> Issue Type: Bug
> Components: Broker
> Affects Versions: 5.6.0
> Environment: Tested on Windows (7)
> Reporter: Matthias Vetter
>
> 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 {
> Thread.sleep(10000);
> } 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
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (AMQ-4171) KahaDB / Journal rotateWriteFIle()
sometimes too fast?
Posted by "Timothy Bish (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/AMQ-4171?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13507405#comment-13507405 ]
Timothy Bish commented on AMQ-4171:
-----------------------------------
The getCanonicalPath change makes sense and I've applied that on trunk, not sure what else can be done here.
> KahaDB / Journal rotateWriteFIle() sometimes too fast?
> ------------------------------------------------------
>
> Key: AMQ-4171
> URL: https://issues.apache.org/jira/browse/AMQ-4171
> Project: ActiveMQ
> Issue Type: Bug
> Components: Broker
> Affects Versions: 5.6.0
> Environment: Tested on Windows XP
> Reporter: Matthias Vetter
>
> 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 {
> Thread.sleep(10000);
> } 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
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (AMQ-4171) KahaDB / Journal rotateWriteFIle()
sometimes too fast?
Posted by "Timothy Bish (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/AMQ-4171?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13496244#comment-13496244 ]
Timothy Bish commented on AMQ-4171:
-----------------------------------
This artificial delay is probably just masking some other issue as the allocation of the DataFile object doesn't actually cause a file to be created or read, only when DataFile.openRandomAccessFile is called is the file going to get created.
> KahaDB / Journal rotateWriteFIle() sometimes too fast?
> ------------------------------------------------------
>
> Key: AMQ-4171
> URL: https://issues.apache.org/jira/browse/AMQ-4171
> Project: ActiveMQ
> Issue Type: Bug
> Components: Broker
> Affects Versions: 5.6.0
> Environment: Tested on Windows (7)
> Reporter: Matthias Vetter
>
> 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 {
> Thread.sleep(10000);
> } 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
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (AMQ-4171) KahaDB / Journal rotateWriteFIle()
sometimes too fast?
Posted by "Timothy Bish (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/AMQ-4171?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13503866#comment-13503866 ]
Timothy Bish commented on AMQ-4171:
-----------------------------------
Suggest moving to a later patch release of the JDK could be an issue there with Windows XP.
> KahaDB / Journal rotateWriteFIle() sometimes too fast?
> ------------------------------------------------------
>
> Key: AMQ-4171
> URL: https://issues.apache.org/jira/browse/AMQ-4171
> Project: ActiveMQ
> Issue Type: Bug
> Components: Broker
> Affects Versions: 5.6.0
> Environment: Tested on Windows XP
> Reporter: Matthias Vetter
>
> 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 {
> Thread.sleep(10000);
> } 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
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira