Elasticsearch: FetchPhaseExecutionException with double-nested documents in 7.10.1

[rkrombho]

Elasticsearch version (bin/elasticsearch --version):
Version: 7.10.1, Build: default/deb/1c34507e66d7db1211f66f3513706fdf548736aa/2020-12-05T01:00:33.671820Z, JVM: 15.0.1

Plugins installed:

• repository-s3

JVM version (java -version):

openjdk version "1.8.0_272"
OpenJDK Runtime Environment (build 1.8.0_272-8u272-b10-0+deb9u1-b10)
OpenJDK 64-Bit Server VM (build 25.272-b10, mixed mode)

OS version (uname -a if on a Unix-like system):
Linux <hosname> 4.19.0-0.bpo.9-amd64 #1 SMP Debian 4.19.118-2+deb10u1~bpo9+1 (2020-06-09) x86_64 GNU/Linux

Description of the problem including expected versus actual behavior:
After updating from 7.9.3 to 7.10.1, the majority of our double-nested queries and aggregations result in a index_out_of_bounds_exception during the fetch phase of nested documents.
This happens when there is a double nested document where both nested layers are queried with inner_hits.
This seems to only happen if there is an array with multiple elements on the first nested layer. The queries work as expected if there is just one nested doc in the first layer.

The steps to repdroduce below should give more insight.

I would expect all queries to work as in the previous minor version when specifying a correct query.
This may be related to the avoidance of reloading _source for every inner hit that was introduced in 7.10.0.

The actual IndexOutOfBoundsException happens here in the FetchPhase

Steps to reproduce:

1. Create an Index with a double-nested layer
   bash curl -XPUT -H "Content-Type: application/json" "http://localhost:9200/nested_bug" -d ' { "mappings": { "dynamic": "strict", "properties": { "someField": { "type": "keyword" }, "firstNest": { "type": "nested", "properties": { "secondNest": { "type": "nested", "properties": { "someId": { "type": "keyword" } } } } } } } } '
2. Index a document with >1 nested docs in each nested layer
   bash curl -XPOST -H "Content-Type: application/json" "http://localhost:9200/nested_bug/_doc/1" -d ' { "someField": "someValue", "firstNest": [ { "secondNest": [ { "someId": "abc" }, { "someId": "def" } ] }, { "secondNest": [ { "someId": "qqq" }, { "someId": "qqq" } ] } ] } '
3. Run a nested > nested query with inner_hits on both. _(While this query doesn't really make sense in this context, we use such queries to get sorted inner hits back)_
   bash curl -XPOST -H "Content-Type: application/json" "http://localhost:9200/nested_bug/_search" -d ' { "_source": ["someField"], "query": { "bool": { "filter": [ { "term": { "someField": "someValue" } }, { "nested": { "path": "firstNest", "inner_hits": { "_source": [ "firstNest.someField" ], "size" : 100 }, "query": { "nested": { "path": "firstNest.secondNest", "inner_hits": { "_source": [ "firstNest.secondNest.someId" ], "size" : 25 }, "query": { "term" : { "firstNest.secondNest.someId": "qqq" } } } } } } ] } } } '

Note: This error does not happen, if the indexed document only contains one firstNest document like that:
```bash
curl -XPOST -H "Content-Type: application/json" "http://localhost:9200/nested_bug/_doc/1" -d '
{
"someField": "someValue",
"firstNest": [
{
"secondNest": [
{
"someId": "abc"
},
{
"someId": "def"
}
]
}
]
}
'

**Provide logs (if relevant)**:

[2020-12-18T10:06:03,816][TRACE][o.e.s.q.QueryPhase ] [10.0.2.15] [nested_bug][0] source[{"query":{"bool":{"filter":[{"term":{"someField":{"value":"someValue","boost":1.0}}},{"nested":{"query":{"nested"
:{"query":{"term":{"firstNest.secondNest.someId":{"value":"qqq","boost":1.0}}},"path":"firstNest.secondNest","ignore_unmapped":false,"score_mode":"avg","boost":1.0,"inner_hits":{"ignore_unmapped":false,"from"
:0,"size":25,"version":false,"seq_no_primary_term":false,"explain":false,"track_scores":false,"_source":{"includes":["firstNest.secondNest.someId"],"excludes":[]},"sort":[]}}},"path":"firstNest","ignore_unmap
ped":false,"score_mode":"avg","boost":1.0,"inner_hits":{"ignore_unmapped":false,"from":0,"size":100,"version":false,"seq_no_primary_term":false,"explain":false,"track_scores":false,"_source":{"includes":["fir
stNest.someField"],"excludes":[]},"sort":[]}}}],"adjust_pure_negative":true,"boost":1.0}},"_source":{"includes":["someField"],"excludes":[]}}], id[],
[2020-12-18T10:06:03,816][TRACE][o.e.s.f.FetchPhase ] [10.0.2.15] [nested_bug][0] source[{"query":{"bool":{"filter":[{"term":{"someField":{"value":"someValue","boost":1.0}}},{"nested":{"query":{"nested"
:{"query":{"term":{"firstNest.secondNest.someId":{"value":"qqq","boost":1.0}}},"path":"firstNest.secondNest","ignore_unmapped":false,"score_mode":"avg","boost":1.0,"inner_hits":{"ignore_unmapped":false,"from"
:0,"size":25,"version":false,"seq_no_primary_term":false,"explain":false,"track_scores":false,"_source":{"includes":["firstNest.secondNest.someId"],"excludes":[]},"sort":[]}}},"path":"firstNest","ignore_unmap
ped":false,"score_mode":"avg","boost":1.0,"inner_hits":{"ignore_unmapped":false,"from":0,"size":100,"version":false,"seq_no_primary_term":false,"explain":false,"track_scores":false,"_source":{"includes":["fir
stNest.someField"],"excludes":[]},"sort":[]}}}],"adjust_pure_negative":true,"boost":1.0}},"_source":{"includes":["someField"],"excludes":[]}}], id[],
[2020-12-18T10:06:03,816][TRACE][o.e.s.f.FetchPhase ] [10.0.2.15] [nested_bug][0] source[{"query":{"bool":{"filter":[{"term":{"someField":{"value":"someValue","boost":1.0}}},{"nested":{"query":{"nested"
:{"query":{"term":{"firstNest.secondNest.someId":{"value":"qqq","boost":1.0}}},"path":"firstNest.secondNest","ignore_unmapped":false,"score_mode":"avg","boost":1.0,"inner_hits":{"ignore_unmapped":false,"from"
:0,"size":25,"version":false,"seq_no_primary_term":false,"explain":false,"track_scores":false,"_source":{"includes":["firstNest.secondNest.someId"],"excludes":[]},"sort":[]}}},"path":"firstNest","ignore_unmap
ped":false,"score_mode":"avg","boost":1.0,"inner_hits":{"ignore_unmapped":false,"from":0,"size":100,"version":false,"seq_no_primary_term":false,"explain":false,"track_scores":false,"_source":{"includes":["fir
stNest.someField"],"excludes":[]},"sort":[]}}}],"adjust_pure_negative":true,"boost":1.0}},"_source":{"includes":["someField"],"excludes":[]}}], id[],
[2020-12-18T10:06:03,817][TRACE][o.e.s.f.FetchPhase ] [10.0.2.15] [nested_bug][0] source[{"query":{"bool":{"filter":[{"term":{"someField":{"value":"someValue","boost":1.0}}},{"nested":{"query":{"nested"
:{"query":{"term":{"firstNest.secondNest.someId":{"value":"qqq","boost":1.0}}},"path":"firstNest.secondNest","ignore_unmapped":false,"score_mode":"avg","boost":1.0,"inner_hits":{"ignore_unmapped":false,"from"
:0,"size":25,"version":false,"seq_no_primary_term":false,"explain":false,"track_scores":false,"_source":{"includes":["firstNest.secondNest.someId"],"excludes":[]},"sort":[]}}},"path":"firstNest","ignore_unmap
ped":false,"score_mode":"avg","boost":1.0,"inner_hits":{"ignore_unmapped":false,"from":0,"size":100,"version":false,"seq_no_primary_term":false,"explain":false,"track_scores":false,"_source":{"includes":["fir
stNest.someField"],"excludes":[]},"sort":[]}}}],"adjust_pure_negative":true,"boost":1.0}},"_source":{"includes":["someField"],"excludes":[]}}], id[],
[2020-12-18T10:06:03,817][TRACE][o.e.s.SearchService ] [10.0.2.15] Query phase failed
org.elasticsearch.search.fetch.FetchPhaseExecutionException: Fetch Failed [Error running fetch phase for doc [6]]
at org.elasticsearch.search.fetch.FetchPhase.execute(FetchPhase.java:168) ~[elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.search.SearchService.executeFetchPhase(SearchService.java:462) ~[elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.search.SearchService.executeQueryPhase(SearchService.java:438) [elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.search.SearchService.access$500(SearchService.java:141) [elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.search.SearchService$2.lambda$onResponse$0(SearchService.java:401) [elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.action.ActionRunnable.lambda$supply$0(ActionRunnable.java:58) [elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.action.ActionRunnable$2.doRun(ActionRunnable.java:73) [elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37) [elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.common.util.concurrent.TimedRunnable.doRun(TimedRunnable.java:44) [elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:737) [elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37) [elasticsearch-7.10.1.jar:7.10.1]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) [?:?]
at java.lang.Thread.run(Thread.java:832) [?:?]
Caused by: org.elasticsearch.search.fetch.FetchPhaseExecutionException: Fetch Failed [Error running fetch phase for doc [5]]
at org.elasticsearch.search.fetch.FetchPhase.execute(FetchPhase.java:168) ~[elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.search.fetch.subphase.InnerHitsPhase.hitExecute(InnerHitsPhase.java:89) ~[elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.search.fetch.subphase.InnerHitsPhase.access$000(InnerHitsPhase.java:40) ~[elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.search.fetch.subphase.InnerHitsPhase$1.process(InnerHitsPhase.java:62) ~[elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.search.fetch.FetchPhase.execute(FetchPhase.java:164) ~[elasticsearch-7.10.1.jar:7.10.1]
... 13 more
Caused by: org.elasticsearch.search.fetch.FetchPhaseExecutionException: Fetch Failed [Error running fetch phase for doc [3]]
at org.elasticsearch.search.fetch.FetchPhase.execute(FetchPhase.java:168) ~[elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.search.fetch.subphase.InnerHitsPhase.hitExecute(InnerHitsPhase.java:89) ~[elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.search.fetch.subphase.InnerHitsPhase.access$000(InnerHitsPhase.java:40) ~[elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.search.fetch.subphase.InnerHitsPhase$1.process(InnerHitsPhase.java:62) ~[elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.search.fetch.FetchPhase.execute(FetchPhase.java:164) ~[elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.search.fetch.subphase.InnerHitsPhase.hitExecute(InnerHitsPhase.java:89) ~[elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.search.fetch.subphase.InnerHitsPhase.access$000(InnerHitsPhase.java:40) ~[elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.search.fetch.subphase.InnerHitsPhase$1.process(InnerHitsPhase.java:62) ~[elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.search.fetch.FetchPhase.execute(FetchPhase.java:164) ~[elasticsearch-7.10.1.jar:7.10.1]
... 13 more
Caused by: java.lang.IndexOutOfBoundsException: Index: 1, Size: 1
at java.util.Collections$SingletonList.get(Collections.java:4926) ~[?:?]
at org.elasticsearch.search.fetch.FetchPhase.prepareNestedHitContext(FetchPhase.java:448) ~[elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.search.fetch.FetchPhase.prepareHitContext(FetchPhase.java:292) ~[elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.search.fetch.FetchPhase.execute(FetchPhase.java:155) ~[elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.search.fetch.subphase.InnerHitsPhase.hitExecute(InnerHitsPhase.java:89) ~[elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.search.fetch.subphase.InnerHitsPhase.access$000(InnerHitsPhase.java:40) ~[elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.search.fetch.subphase.InnerHitsPhase$1.process(InnerHitsPhase.java:62) ~[elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.search.fetch.FetchPhase.execute(FetchPhase.java:164) ~[elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.search.fetch.subphase.InnerHitsPhase.hitExecute(InnerHitsPhase.java:89) ~[elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.search.fetch.subphase.InnerHitsPhase.access$000(InnerHitsPhase.java:40) ~[elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.search.fetch.subphase.InnerHitsPhase$1.process(InnerHitsPhase.java:62) ~[elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.search.fetch.FetchPhase.execute(FetchPhase.java:164) ~[elasticsearch-7.10.1.jar:7.10.1]
... 13 more
[2020-12-18T10:06:03,818][WARN ][r.suppressed ] [10.0.2.15] path: /nested_bug/_search, params: {index=nested_bug}
org.elasticsearch.action.search.SearchPhaseExecutionException: all shards failed
at org.elasticsearch.action.search.AbstractSearchAsyncAction.onPhaseFailure(AbstractSearchAsyncAction.java:568) [elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.action.search.AbstractSearchAsyncAction.executeNextPhase(AbstractSearchAsyncAction.java:324) [elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.action.search.AbstractSearchAsyncAction.onPhaseDone(AbstractSearchAsyncAction.java:603) [elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.action.search.AbstractSearchAsyncAction.onShardFailure(AbstractSearchAsyncAction.java:400) [elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.action.search.AbstractSearchAsyncAction.access$100(AbstractSearchAsyncAction.java:70) [elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.action.search.AbstractSearchAsyncAction$1.onFailure(AbstractSearchAsyncAction.java:258) [elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.action.search.SearchExecutionStatsCollector.onFailure(SearchExecutionStatsCollector.java:73) [elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.action.ActionListenerResponseHandler.handleException(ActionListenerResponseHandler.java:59) [elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.action.search.SearchTransportService$ConnectionCountingHandler.handleException(SearchTransportService.java:408) [elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.transport.TransportService$6.handleException(TransportService.java:640) [elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.transport.TransportService$ContextRestoreResponseHandler.handleException(TransportService.java:1181) [elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.transport.TransportService$DirectResponseChannel.processException(TransportService.java:1290) [elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.transport.TransportService$DirectResponseChannel.sendResponse(TransportService.java:1264) [elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.transport.TaskTransportChannel.sendResponse(TaskTransportChannel.java:61) [elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.transport.TransportChannel.sendErrorResponse(TransportChannel.java:56) [elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.action.support.ChannelActionListener.onFailure(ChannelActionListener.java:51) [elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.action.ActionRunnable.onFailure(ActionRunnable.java:88) [elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:39) [elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.common.util.concurrent.TimedRunnable.doRun(TimedRunnable.java:44) [elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:737) [elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37) [elasticsearch-7.10.1.jar:7.10.1]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) [?:?]
at java.lang.Thread.run(Thread.java:832) [?:?]
Caused by: org.elasticsearch.ElasticsearchException$1: Index: 1, Size: 1
at org.elasticsearch.ElasticsearchException.guessRootCauses(ElasticsearchException.java:644) ~[elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.action.search.AbstractSearchAsyncAction.executeNextPhase(AbstractSearchAsyncAction.java:322) [elasticsearch-7.10.1.jar:7.10.1]
... 22 more
Caused by: java.lang.IndexOutOfBoundsException: Index: 1, Size: 1
at java.util.Collections$SingletonList.get(Collections.java:4926) ~[?:?]
at org.elasticsearch.search.fetch.FetchPhase.prepareNestedHitContext(FetchPhase.java:448) ~[elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.search.fetch.FetchPhase.prepareHitContext(FetchPhase.java:292) ~[elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.search.fetch.FetchPhase.execute(FetchPhase.java:155) ~[elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.search.fetch.subphase.InnerHitsPhase.hitExecute(InnerHitsPhase.java:89) ~[elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.search.fetch.subphase.InnerHitsPhase.access$000(InnerHitsPhase.java:40) ~[elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.search.fetch.subphase.InnerHitsPhase$1.process(InnerHitsPhase.java:62) ~[elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.search.fetch.FetchPhase.execute(FetchPhase.java:164) ~[elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.search.fetch.subphase.InnerHitsPhase.hitExecute(InnerHitsPhase.java:89) ~[elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.search.fetch.subphase.InnerHitsPhase.access$000(InnerHitsPhase.java:40) ~[elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.search.fetch.subphase.InnerHitsPhase$1.process(InnerHitsPhase.java:62) ~[elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.search.fetch.FetchPhase.execute(FetchPhase.java:164) ~[elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.search.SearchService.executeFetchPhase(SearchService.java:462) ~[elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.search.SearchService.executeQueryPhase(SearchService.java:438) ~[elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.search.SearchService.access$500(SearchService.java:141) ~[elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.search.SearchService$2.lambda$onResponse$0(SearchService.java:401) ~[elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.action.ActionRunnable.lambda$supply$0(ActionRunnable.java:58) ~[elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.action.ActionRunnable$2.doRun(ActionRunnable.java:73) ~[elasticsearch-7.10.1.jar:7.10.1]
at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37) ~[elasticsearch-7.10.1.jar:7.10.1]
... 6 more
```

[elasticmachine]

Pinging @elastic/es-search (Team:Search)

[rkrombho]

Thank you for the changes!
Do you think that we can expect a 7.10.x hotfix release after this is integrated?
It's quite severe for anyone upgrading to 7.10.x while using at least two layers of nested.

Maybe this issue should also be mentioned in the "Known issues" list of the 7.10.x release notes

[jtibshirani]

Thanks @rkrombho for reporting this and sorry for the trouble it caused you. I agree it's a serious regression, but I don't think we plan to hotfix. It will be available in the upcoming 7.10.2 and 7.11 releases. I'll be sure to add a note to 'Known issues'.