Server crashes when posting documents and searching them immediately afterwards

ajsie · July 26, 2011, 8:41am

I have a test that does a bulk post of documents into 3 indices and
immediately afterwards does a _search.

It fails due to that the documents are not indexed yet for search and
the server also crashes:

[2011-07-26 10:38:06,706][INFO ][cluster.metadata ]
[Robertson, Robbie] [apple.com] deleting index
[2011-07-26 10:38:06,774][INFO ][cluster.metadata ]
[Robertson, Robbie] [google.com] deleting index
[2011-07-26 10:38:06,929][INFO ][cluster.metadata ]
[Robertson, Robbie] [google.com] creating index, cause [api], shards
[5]/[1], mappings []
[2011-07-26 10:38:07,137][INFO ][cluster.metadata ]
[Robertson, Robbie] [apple.com] creating index, cause [api], shards
[5]/[1], mappings []
[2011-07-26 10:38:07,985][INFO ][cluster.metadata ]
[Robertson, Robbie] [microsoft.com] creating index, cause [api],
shards [5]/[1], mappings []
[2011-07-26 10:38:08,187][INFO ][cluster.metadata ]
[Robertson, Robbie] [google.com] update_mapping [product] (dynamic)
[2011-07-26 10:38:08,232][INFO ][cluster.metadata ]
[Robertson, Robbie] [apple.com] update_mapping [user] (dynamic)
[2011-07-26 10:38:08,245][INFO ][cluster.metadata ]
[Robertson, Robbie] [apple.com] update_mapping [product] (dynamic)
[2011-07-26 10:38:08,252][INFO ][cluster.metadata ]
[Robertson, Robbie] [google.com] update_mapping [user] (dynamic)
[2011-07-26 10:38:08,546][INFO ][cluster.metadata ]
[Robertson, Robbie] [microsoft.com] update_mapping [user] (dynamic)
[2011-07-26 10:38:08,560][INFO ][cluster.metadata ]
[Robertson, Robbie] [microsoft.com] update_mapping [product] (dynamic)
[2011-07-26 10:38:09,126][INFO ][cluster.metadata ]
[Robertson, Robbie] [microsoft.com] deleting index
[2011-07-26 10:38:09,139][WARN ][index.shard.service ]
[Robertson, Robbie] [microsoft.com][3] Failed to perform scheduled
engine refresh
org.elasticsearch.index.engine.RefreshFailedEngineException:
[microsoft.com][3] Refresh failed
at
org.elasticsearch.index.engine.robin.RobinEngine.refresh(RobinEngine.java:
762)
at
org.elasticsearch.index.shard.service.InternalIndexShard.refresh(InternalIndexShard.java:
384)
at org.elasticsearch.index.shard.service.InternalIndexShard
$EngineRefresher$1.run(InternalIndexShard.java:613)
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:680)
Caused by: java.io.FileNotFoundException: /Volumes/Private/johnnyluu/
Documents/Development/third_party/elasticsearch-0.17.1/data/
elasticsearch/nodes/0/indices/microsoft.com/3/index/_0.fnm (No such
file or directory)
at java.io.RandomAccessFile.open(Native Method)
at java.io.RandomAccessFile.(RandomAccessFile.java:216)
at org.apache.lucene.store.SimpleFSDirectory$SimpleFSIndexInput
$Descriptor.(SimpleFSDirectory.java:69)
at org.apache.lucene.store.SimpleFSDirectory
$SimpleFSIndexInput.(SimpleFSDirectory.java:90)
at org.apache.lucene.store.NIOFSDirectory
$NIOFSIndexInput.(NIOFSDirectory.java:91)
at
org.apache.lucene.store.NIOFSDirectory.openInput(NIOFSDirectory.java:
78)
at org.apache.lucene.store.FSDirectory.openInput(FSDirectory.java:
345)
at org.elasticsearch.index.store.support.AbstractStore
$StoreDirectory.openInput(AbstractStore.java:328)
at org.apache.lucene.index.FieldInfos.(FieldInfos.java:68)
at
org.apache.lucene.index.SegmentCoreReaders.(SegmentCoreReaders.java:
72)
at org.apache.lucene.index.SegmentReader.get(SegmentReader.java:114)
at org.apache.lucene.index.IndexWriter
$ReaderPool.get(IndexWriter.java:702)
at org.apache.lucene.index.IndexWriter
$ReaderPool.getReadOnlyClone(IndexWriter.java:660)
at
org.apache.lucene.index.DirectoryReader.(DirectoryReader.java:
157)
at
org.apache.lucene.index.ReadOnlyDirectoryReader.(ReadOnlyDirectoryReader.java:
38)
at org.apache.lucene.index.IndexWriter.getReader(IndexWriter.java:
459)
at org.apache.lucene.index.IndexWriter.getReader(IndexWriter.java:
407)
at
org.apache.lucene.index.DirectoryReader.doReopenFromWriter(DirectoryReader.java:
414)
at
org.apache.lucene.index.DirectoryReader.doReopen(DirectoryReader.java:
427)
at
org.apache.lucene.index.DirectoryReader.reopen(DirectoryReader.java:
392)
at
org.elasticsearch.index.engine.robin.RobinEngine.refresh(RobinEngine.java:
745)
... 5 more
[2011-07-26 10:38:09,161][INFO ][cluster.metadata ]
[Robertson, Robbie] [apple.com] deleting index
[2011-07-26 10:38:09,202][INFO ][cluster.metadata ]
[Robertson, Robbie] [google.com] deleting index
[2011-07-26 10:38:09,354][INFO ][cluster.metadata ]
[Robertson, Robbie] [google.com] creating index, cause [api], shards
[5]/[1], mappings []
[2011-07-26 10:38:09,491][INFO ][cluster.metadata ]
[Robertson, Robbie] [apple.com] creating index, cause [api], shards
[5]/[1], mappings []
[2011-07-26 10:38:09,897][INFO ][cluster.metadata ]
[Robertson, Robbie] [microsoft.com] creating index, cause [api],
shards [5]/[1], mappings []

Is this a bug?

kimchy · July 26, 2011, 9:08am

Few questions:

Do the server really crash? As in exits?
You delete the index microsoft.com, and then get the async refresh
failure (its a scheduled refresh that goes and tries to refresh the index).
You can safely ignore this failure, though it should not be logged.
In elasticsearch, when you index a document, its indexed, but not
immediately visible for search. By default, there is an async refresh going
on (happens every 1 second) that refreshes all the changes happened in that
period and makes it visible for search. The refresh API allows you to do it
explicitly, though, note, it does come at a cost, so you would not want to
refresh after every document you index.

-shay.banon

On Tue, Jul 26, 2011 at 11:41 AM, ajsie johnny.weng.luu@gmail.com wrote:

I have a test that does a bulk post of documents into 3 indices and
immediately afterwards does a _search.

It fails due to that the documents are not indexed yet for search and
the server also crashes:

[2011-07-26 10:38:06,706][INFO ][cluster.metadata ]
[Robertson, Robbie] [apple.com] deleting index
[2011-07-26 10:38:06,774][INFO ][cluster.metadata ]
[Robertson, Robbie] [google.com] deleting index
[2011-07-26 10:38:06,929][INFO ][cluster.metadata ]
[Robertson, Robbie] [google.com] creating index, cause [api], shards
[5]/[1], mappings
[2011-07-26 10:38:07,137][INFO ][cluster.metadata ]
[Robertson, Robbie] [apple.com] creating index, cause [api], shards
[5]/[1], mappings
[2011-07-26 10:38:07,985][INFO ][cluster.metadata ]
[Robertson, Robbie] [microsoft.com] creating index, cause [api],
shards [5]/[1], mappings
[2011-07-26 10:38:08,187][INFO ][cluster.metadata ]
[Robertson, Robbie] [google.com] update_mapping [product] (dynamic)
[2011-07-26 10:38:08,232][INFO ][cluster.metadata ]
[Robertson, Robbie] [apple.com] update_mapping [user] (dynamic)
[2011-07-26 10:38:08,245][INFO ][cluster.metadata ]
[Robertson, Robbie] [apple.com] update_mapping [product] (dynamic)
[2011-07-26 10:38:08,252][INFO ][cluster.metadata ]
[Robertson, Robbie] [google.com] update_mapping [user] (dynamic)
[2011-07-26 10:38:08,546][INFO ][cluster.metadata ]
[Robertson, Robbie] [microsoft.com] update_mapping [user] (dynamic)
[2011-07-26 10:38:08,560][INFO ][cluster.metadata ]
[Robertson, Robbie] [microsoft.com] update_mapping [product] (dynamic)
[2011-07-26 10:38:09,126][INFO ][cluster.metadata ]
[Robertson, Robbie] [microsoft.com] deleting index
[2011-07-26 10:38:09,139][WARN ][index.shard.service ]
[Robertson, Robbie] [microsoft.com][3] Failed to perform scheduled
engine refresh
org.elasticsearch.index.engine.RefreshFailedEngineException:
[microsoft.com][3] Refresh failed
at
org.elasticsearch.index.engine.robin.RobinEngine.refresh(RobinEngine.java:
762)
at

org.elasticsearch.index.shard.service.InternalIndexShard.refresh(InternalIndexShard.java:
384)
at org.elasticsearch.index.shard.service.InternalIndexShard
$EngineRefresher$1.run(InternalIndexShard.java:613)
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:680)
Caused by: java.io.FileNotFoundException: /Volumes/Private/johnnyluu/
Documents/Development/third_party/elasticsearch-0.17.1/data/
elasticsearch/nodes/0/indices/microsoft.com/3/index/_0.fnm (No such
file or directory)
at java.io.RandomAccessFile.open(Native Method)
at java.io.RandomAccessFile.(RandomAccessFile.java:216)
at org.apache.lucene.store.SimpleFSDirectory$SimpleFSIndexInput
$Descriptor.(SimpleFSDirectory.java:69)
at org.apache.lucene.store.SimpleFSDirectory
$SimpleFSIndexInput.(SimpleFSDirectory.java:90)
at org.apache.lucene.store.NIOFSDirectory
$NIOFSIndexInput.(NIOFSDirectory.java:91)
at
org.apache.lucene.store.NIOFSDirectory.openInput(NIOFSDirectory.java:
78)
at org.apache.lucene.store.FSDirectory.openInput(FSDirectory.java:
345)
at org.elasticsearch.index.store.support.AbstractStore
$StoreDirectory.openInput(AbstractStore.java:328)
at org.apache.lucene.index.FieldInfos.(FieldInfos.java:68)
at
org.apache.lucene.index.SegmentCoreReaders.(SegmentCoreReaders.java:
72)
at org.apache.lucene.index.SegmentReader.get(SegmentReader.java:114)
at org.apache.lucene.index.IndexWriter
$ReaderPool.get(IndexWriter.java:702)
at org.apache.lucene.index.IndexWriter
$ReaderPool.getReadOnlyClone(IndexWriter.java:660)
at
org.apache.lucene.index.DirectoryReader.(DirectoryReader.java:
157)
at

org.apache.lucene.index.ReadOnlyDirectoryReader.(ReadOnlyDirectoryReader.java:
38)
at org.apache.lucene.index.IndexWriter.getReader(IndexWriter.java:
459)
at org.apache.lucene.index.IndexWriter.getReader(IndexWriter.java:
407)
at

org.apache.lucene.index.DirectoryReader.doReopenFromWriter(DirectoryReader.java:
414)
at
org.apache.lucene.index.DirectoryReader.doReopen(DirectoryReader.java:
427)
at
org.apache.lucene.index.DirectoryReader.reopen(DirectoryReader.java:
392)
at
org.elasticsearch.index.engine.robin.RobinEngine.refresh(RobinEngine.java:
745)
... 5 more
[2011-07-26 10:38:09,161][INFO ][cluster.metadata ]
[Robertson, Robbie] [apple.com] deleting index
[2011-07-26 10:38:09,202][INFO ][cluster.metadata ]
[Robertson, Robbie] [google.com] deleting index
[2011-07-26 10:38:09,354][INFO ][cluster.metadata ]
[Robertson, Robbie] [google.com] creating index, cause [api], shards
[5]/[1], mappings
[2011-07-26 10:38:09,491][INFO ][cluster.metadata ]
[Robertson, Robbie] [apple.com] creating index, cause [api], shards
[5]/[1], mappings
[2011-07-26 10:38:09,897][INFO ][cluster.metadata ]
[Robertson, Robbie] [microsoft.com] creating index, cause [api],
shards [5]/[1], mappings

Is this a bug?