Intermittent SearchPhaseExecutionException, caused by NPE


(James K) #1

Hello everyone, I'm seeing intermittent failures using Elasticsearch v
0.16.0. The same query can work and fail. There may be some
correlation with a bulk load running simultaneously. Has anyone seen
similar behavior?

Here's my query (this is a histogram, but the same query w/o the
facets will exhibit the same problem)

{"filter":{"and":[{"terms":{"forum_id":[2]}},{"query":{"query_string":
{"default_field":"body","query":"testing"}}}]},"facets":{"histo1":
{"date_histogram":{"field":"date","interval":"7d"}}}}'

Here's the error from elastic search:

{"error":"SearchPhaseExecutionException[Failed to execute phase
[query], total failure; shardFailures {[2ZvjA8pITz2jpyJYq1kinw]
[landscape][0]: QueryPhaseExecutionException[[landscape][0]:
query[ConstantScore(:)],from[0],size[10]: Query Failed [Failed to
execute main query]]; nested: }{[2ZvjA8pITz2jpyJYq1kinw][landscape]
[1]: QueryPhaseExecutionException[[landscape][1]:
query[ConstantScore(:)],from[0],size[10]: Query Failed [Failed to
execute main query]]; nested: }{[2ZvjA8pITz2jpyJYq1kinw][landscape]
[2]: QueryPhaseExecutionException[[landscape][2]:
query[ConstantScore(:)],from[0],size[10]: Query Failed [Failed to
execute main query]]; nested: }{[2ZvjA8pITz2jpyJYq1kinw][landscape]
[3]: QueryPhaseExecutionException[[landscape][3]:
query[ConstantScore(:)],from[0],size[10]: Query Failed [Failed to
execute main query]]; nested: }{[2ZvjA8pITz2jpyJYq1kinw][landscape]
[4]: QueryPhaseExecutionException[[landscape][4]:
query[ConstantScore(:)],from[0],size[10]: Query Failed [Failed to
execute main query]]; nested: }]","status":500}

And a slice of the elastic search log file (this NPE can happen even
when the query returns successfully)

[2011-05-03 16:21:52,422][DEBUG][action.search.type ] [Banner,
Betty Ross] [landscape][4], node[2ZvjA8pITz2jpyJYq1kinw], [P],
s[STARTED]: Failed to execute
[org.elasticsearch.action.search.SearchRequest@4f2ff706]
org.elasticsearch.search.query.QueryPhaseExecutionException:
[landscape][4]: query[ConstantScore(:)],from[0],size[10]: Query
Failed [Failed to execute main query]
at org.elasticsearch.search.query.QueryPhase.execute(QueryPhase.java:
215)
at
org.elasticsearch.search.SearchService.executeQueryPhase(SearchService.java:
222)
at
org.elasticsearch.search.action.SearchServiceTransportAction.sendExecuteQuery(SearchServiceTransportAction.java:
134)
at
org.elasticsearch.action.search.type.TransportSearchQueryThenFetchAction
$AsyncAction.sendExecuteFirstPhase(TransportSearchQueryThenFetchAction.java:
76)
at org.elasticsearch.action.search.type.TransportSearchTypeAction
$BaseAsyncAction.performFirstPhase(TransportSearchTypeAction.java:192)
at org.elasticsearch.action.search.type.TransportSearchTypeAction
$BaseAsyncAction.access$000(TransportSearchTypeAction.java:75)
at org.elasticsearch.action.search.type.TransportSearchTypeAction
$BaseAsyncAction$1.run(TransportSearchTypeAction.java:151)
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.lang.NullPointerException


(Shay Banon) #2

Can you gist the rest of the stack trace? The one below the NPE is the important part.
On Tuesday, May 3, 2011 at 11:28 PM, James K wrote:

Hello everyone, I'm seeing intermittent failures using Elasticsearch v
0.16.0. The same query can work and fail. There may be some
correlation with a bulk load running simultaneously. Has anyone seen
similar behavior?

Here's my query (this is a histogram, but the same query w/o the
facets will exhibit the same problem)

{"filter":{"and":[{"terms":{"forum_id":[2]}},{"query":{"query_string":
{"default_field":"body","query":"testing"}}}]},"facets":{"histo1":
{"date_histogram":{"field":"date","interval":"7d"}}}}'

Here's the error from elastic search:

{"error":"SearchPhaseExecutionException[Failed to execute phase
[query], total failure; shardFailures {[2ZvjA8pITz2jpyJYq1kinw]
[landscape][0]: QueryPhaseExecutionException[[landscape][0]:
query[ConstantScore(:)],from[0],size[10]: Query Failed [Failed to
execute main query]]; nested: }{[2ZvjA8pITz2jpyJYq1kinw][landscape]
[1]: QueryPhaseExecutionException[[landscape][1]:
query[ConstantScore(:)],from[0],size[10]: Query Failed [Failed to
execute main query]]; nested: }{[2ZvjA8pITz2jpyJYq1kinw][landscape]
[2]: QueryPhaseExecutionException[[landscape][2]:
query[ConstantScore(:)],from[0],size[10]: Query Failed [Failed to
execute main query]]; nested: }{[2ZvjA8pITz2jpyJYq1kinw][landscape]
[3]: QueryPhaseExecutionException[[landscape][3]:
query[ConstantScore(:)],from[0],size[10]: Query Failed [Failed to
execute main query]]; nested: }{[2ZvjA8pITz2jpyJYq1kinw][landscape]
[4]: QueryPhaseExecutionException[[landscape][4]:
query[ConstantScore(:)],from[0],size[10]: Query Failed [Failed to
execute main query]]; nested: }]","status":500}

And a slice of the elastic search log file (this NPE can happen even
when the query returns successfully)

[2011-05-03 16:21:52,422][DEBUG][action.search.type ] [Banner,
Betty Ross] [landscape][4], node[2ZvjA8pITz2jpyJYq1kinw], [P],
s[STARTED]: Failed to execute
[org.elasticsearch.action.search.SearchRequest@4f2ff706]
org.elasticsearch.search.query.QueryPhaseExecutionException:
[landscape][4]: query[ConstantScore(:)],from[0],size[10]: Query
Failed [Failed to execute main query]
at org.elasticsearch.search.query.QueryPhase.execute(QueryPhase.java:
215)
at
org.elasticsearch.search.SearchService.executeQueryPhase(SearchService.java:
222)
at
org.elasticsearch.search.action.SearchServiceTransportAction.sendExecuteQuery(SearchServiceTransportAction.java:
134)
at
org.elasticsearch.action.search.type.TransportSearchQueryThenFetchAction
$AsyncAction.sendExecuteFirstPhase(TransportSearchQueryThenFetchAction.java:
76)
at org.elasticsearch.action.search.type.TransportSearchTypeAction
$BaseAsyncAction.performFirstPhase(TransportSearchTypeAction.java:192)
at org.elasticsearch.action.search.type.TransportSearchTypeAction
$BaseAsyncAction.access$000(TransportSearchTypeAction.java:75)
at org.elasticsearch.action.search.type.TransportSearchTypeAction
$BaseAsyncAction$1.run(TransportSearchTypeAction.java:151)
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.lang.NullPointerException


(James K) #3

Sure, here https://gist.github.com/954205

On May 3, 4:47 pm, Shay Banon shay.ba...@elasticsearch.com wrote:

Can you gist the rest of the stack trace? The one below the NPE is the important part.

On Tuesday, May 3, 2011 at 11:28 PM, James K wrote:

Hello everyone, I'm seeing intermittent failures using Elasticsearch v
0.16.0. The same query can work and fail. There may be some
correlation with a bulk load running simultaneously. Has anyone seen
similar behavior?

Here's my query (this is a histogram, but the same query w/o the
facets will exhibit the same problem)

{"filter":{"and":[{"terms":{"forum_id":[2]}},{"query":{"query_string":
{"default_field":"body","query":"testing"}}}]},"facets":{"histo1":
{"date_histogram":{"field":"date","interval":"7d"}}}}'

Here's the error from elastic search:

{"error":"SearchPhaseExecutionException[Failed to execute phase
[query], total failure; shardFailures {[2ZvjA8pITz2jpyJYq1kinw]
[landscape][0]: QueryPhaseExecutionException[[landscape][0]:
query[ConstantScore(:)],from[0],size[10]: Query Failed [Failed to
execute main query]]; nested: }{[2ZvjA8pITz2jpyJYq1kinw][landscape]
[1]: QueryPhaseExecutionException[[landscape][1]:
query[ConstantScore(:)],from[0],size[10]: Query Failed [Failed to
execute main query]]; nested: }{[2ZvjA8pITz2jpyJYq1kinw][landscape]
[2]: QueryPhaseExecutionException[[landscape][2]:
query[ConstantScore(:)],from[0],size[10]: Query Failed [Failed to
execute main query]]; nested: }{[2ZvjA8pITz2jpyJYq1kinw][landscape]
[3]: QueryPhaseExecutionException[[landscape][3]:
query[ConstantScore(:)],from[0],size[10]: Query Failed [Failed to
execute main query]]; nested: }{[2ZvjA8pITz2jpyJYq1kinw][landscape]
[4]: QueryPhaseExecutionException[[landscape][4]:
query[ConstantScore(:)],from[0],size[10]: Query Failed [Failed to
execute main query]]; nested: }]","status":500}

And a slice of the elastic search log file (this NPE can happen even
when the query returns successfully)

[2011-05-03 16:21:52,422][DEBUG][action.search.type ] [Banner,
Betty Ross] [landscape][4], node[2ZvjA8pITz2jpyJYq1kinw], [P],
s[STARTED]: Failed to execute
[org.elasticsearch.action.search.SearchRequest@4f2ff706]
org.elasticsearch.search.query.QueryPhaseExecutionException:
[landscape][4]: query[ConstantScore(:)],from[0],size[10]: Query
Failed [Failed to execute main query]
at org.elasticsearch.search.query.QueryPhase.execute(QueryPhase.java:
215)
at
org.elasticsearch.search.SearchService.executeQueryPhase(SearchService.java:
222)
at
org.elasticsearch.search.action.SearchServiceTransportAction.sendExecuteQuery(SearchServiceTransportAction.java:
134)
at
org.elasticsearch.action.search.type.TransportSearchQueryThenFetchAction
$AsyncAction.sendExecuteFirstPhase(TransportSearchQueryThenFetchAction.java:
76)
at org.elasticsearch.action.search.type.TransportSearchTypeAction
$BaseAsyncAction.performFirstPhase(TransportSearchTypeAction.java:192)
at org.elasticsearch.action.search.type.TransportSearchTypeAction
$BaseAsyncAction.access$000(TransportSearchTypeAction.java:75)
at org.elasticsearch.action.search.type.TransportSearchTypeAction
$BaseAsyncAction$1.run(TransportSearchTypeAction.java:151)
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.lang.NullPointerException


(Shay Banon) #4

Heya,

Yes, this has been fixed in 0.16 branch, and will be part of 0.16.1 release, slated to happen in a few days.

-shay.banon
On Tuesday, May 3, 2011 at 11:52 PM, James K wrote:

Sure, here https://gist.github.com/954205

On May 3, 4:47 pm, Shay Banon shay.ba...@elasticsearch.com wrote:

Can you gist the rest of the stack trace? The one below the NPE is the important part.

On Tuesday, May 3, 2011 at 11:28 PM, James K wrote:

Hello everyone, I'm seeing intermittent failures using Elasticsearch v
0.16.0. The same query can work and fail. There may be some
correlation with a bulk load running simultaneously. Has anyone seen
similar behavior?

Here's my query (this is a histogram, but the same query w/o the
facets will exhibit the same problem)

{"filter":{"and":[{"terms":{"forum_id":[2]}},{"query":{"query_string":
{"default_field":"body","query":"testing"}}}]},"facets":{"histo1":
{"date_histogram":{"field":"date","interval":"7d"}}}}'

Here's the error from elastic search:

{"error":"SearchPhaseExecutionException[Failed to execute phase
[query], total failure; shardFailures {[2ZvjA8pITz2jpyJYq1kinw]
[landscape][0]: QueryPhaseExecutionException[[landscape][0]:
query[ConstantScore(:)],from[0],size[10]: Query Failed [Failed to
execute main query]]; nested: }{[2ZvjA8pITz2jpyJYq1kinw][landscape]
[1]: QueryPhaseExecutionException[[landscape][1]:
query[ConstantScore(:)],from[0],size[10]: Query Failed [Failed to
execute main query]]; nested: }{[2ZvjA8pITz2jpyJYq1kinw][landscape]
[2]: QueryPhaseExecutionException[[landscape][2]:
query[ConstantScore(:)],from[0],size[10]: Query Failed [Failed to
execute main query]]; nested: }{[2ZvjA8pITz2jpyJYq1kinw][landscape]
[3]: QueryPhaseExecutionException[[landscape][3]:
query[ConstantScore(:)],from[0],size[10]: Query Failed [Failed to
execute main query]]; nested: }{[2ZvjA8pITz2jpyJYq1kinw][landscape]
[4]: QueryPhaseExecutionException[[landscape][4]:
query[ConstantScore(:)],from[0],size[10]: Query Failed [Failed to
execute main query]]; nested: }]","status":500}

And a slice of the elastic search log file (this NPE can happen even
when the query returns successfully)

[2011-05-03 16:21:52,422][DEBUG][action.search.type ] [Banner,
Betty Ross] [landscape][4], node[2ZvjA8pITz2jpyJYq1kinw], [P],
s[STARTED]: Failed to execute
[org.elasticsearch.action.search.SearchRequest@4f2ff706]
org.elasticsearch.search.query.QueryPhaseExecutionException:
[landscape][4]: query[ConstantScore(:)],from[0],size[10]: Query
Failed [Failed to execute main query]
at org.elasticsearch.search.query.QueryPhase.execute(QueryPhase.java:
215)
at
org.elasticsearch.search.SearchService.executeQueryPhase(SearchService.java:
222)
at
org.elasticsearch.search.action.SearchServiceTransportAction.sendExecuteQuery(SearchServiceTransportAction.java:
134)
at
org.elasticsearch.action.search.type.TransportSearchQueryThenFetchAction
$AsyncAction.sendExecuteFirstPhase(TransportSearchQueryThenFetchAction.java:
76)
at org.elasticsearch.action.search.type.TransportSearchTypeAction
$BaseAsyncAction.performFirstPhase(TransportSearchTypeAction.java:192)
at org.elasticsearch.action.search.type.TransportSearchTypeAction
$BaseAsyncAction.access$000(TransportSearchTypeAction.java:75)
at org.elasticsearch.action.search.type.TransportSearchTypeAction
$BaseAsyncAction$1.run(TransportSearchTypeAction.java:151)
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.lang.NullPointerException


(James K) #5

Great, thanks for the speedy feedback!

On May 3, 4:53 pm, Shay Banon shay.ba...@elasticsearch.com wrote:

Heya,

Yes, this has been fixed in 0.16 branch, and will be part of 0.16.1 release, slated to happen in a few days.

-shay.banon

On Tuesday, May 3, 2011 at 11:52 PM, James K wrote:

Sure, herehttps://gist.github.com/954205

On May 3, 4:47 pm, Shay Banon shay.ba...@elasticsearch.com wrote:

Can you gist the rest of the stack trace? The one below the NPE is the important part.

On Tuesday, May 3, 2011 at 11:28 PM, James K wrote:

Hello everyone, I'm seeing intermittent failures using Elasticsearch v
0.16.0. The same query can work and fail. There may be some
correlation with a bulk load running simultaneously. Has anyone seen
similar behavior?

Here's my query (this is a histogram, but the same query w/o the
facets will exhibit the same problem)

{"filter":{"and":[{"terms":{"forum_id":[2]}},{"query":{"query_string":
{"default_field":"body","query":"testing"}}}]},"facets":{"histo1":
{"date_histogram":{"field":"date","interval":"7d"}}}}'

Here's the error from elastic search:

{"error":"SearchPhaseExecutionException[Failed to execute phase
[query], total failure; shardFailures {[2ZvjA8pITz2jpyJYq1kinw]
[landscape][0]: QueryPhaseExecutionException[[landscape][0]:
query[ConstantScore(:)],from[0],size[10]: Query Failed [Failed to
execute main query]]; nested: }{[2ZvjA8pITz2jpyJYq1kinw][landscape]
[1]: QueryPhaseExecutionException[[landscape][1]:
query[ConstantScore(:)],from[0],size[10]: Query Failed [Failed to
execute main query]]; nested: }{[2ZvjA8pITz2jpyJYq1kinw][landscape]
[2]: QueryPhaseExecutionException[[landscape][2]:
query[ConstantScore(:)],from[0],size[10]: Query Failed [Failed to
execute main query]]; nested: }{[2ZvjA8pITz2jpyJYq1kinw][landscape]
[3]: QueryPhaseExecutionException[[landscape][3]:
query[ConstantScore(:)],from[0],size[10]: Query Failed [Failed to
execute main query]]; nested: }{[2ZvjA8pITz2jpyJYq1kinw][landscape]
[4]: QueryPhaseExecutionException[[landscape][4]:
query[ConstantScore(:)],from[0],size[10]: Query Failed [Failed to
execute main query]]; nested: }]","status":500}

And a slice of the elastic search log file (this NPE can happen even
when the query returns successfully)

[2011-05-03 16:21:52,422][DEBUG][action.search.type ] [Banner,
Betty Ross] [landscape][4], node[2ZvjA8pITz2jpyJYq1kinw], [P],
s[STARTED]: Failed to execute
[org.elasticsearch.action.search.SearchRequest@4f2ff706]
org.elasticsearch.search.query.QueryPhaseExecutionException:
[landscape][4]: query[ConstantScore(:)],from[0],size[10]: Query
Failed [Failed to execute main query]
at org.elasticsearch.search.query.QueryPhase.execute(QueryPhase.java:
215)
at
org.elasticsearch.search.SearchService.executeQueryPhase(SearchService.java:
222)
at
org.elasticsearch.search.action.SearchServiceTransportAction.sendExecuteQuery(SearchServiceTransportAction.java:
134)
at
org.elasticsearch.action.search.type.TransportSearchQueryThenFetchAction
$AsyncAction.sendExecuteFirstPhase(TransportSearchQueryThenFetchAction.java:
76)
at org.elasticsearch.action.search.type.TransportSearchTypeAction
$BaseAsyncAction.performFirstPhase(TransportSearchTypeAction.java:192)
at org.elasticsearch.action.search.type.TransportSearchTypeAction
$BaseAsyncAction.access$000(TransportSearchTypeAction.java:75)
at org.elasticsearch.action.search.type.TransportSearchTypeAction
$BaseAsyncAction$1.run(TransportSearchTypeAction.java:151)
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.lang.NullPointerException


(system) #6