ReduceSearchPhaseException Caused by NullPointerException

[Rogier75]

Elasticsearch version: 5.1.1

{
  "name" : "atom1",
  "cluster_name" : "atomcluster",
  "cluster_uuid" : "Ax602ATwRUanUplRc3d5iA",
  "version" : {
    "number" : "5.1.1",
    "build_hash" : "5395e21",
    "build_date" : "2016-12-06T12:36:15.409Z",
    "build_snapshot" : false,
    "lucene_version" : "6.3.0"
  },
  "tagline" : "You Know, for Search"
}

Plugins installed: []
none

JVM version: 1.8.0
[root@atom1 jenkins]# java -version
java version "1.8.0"
Java(TM) SE Runtime Environment (build 1.8.0-b132)
Java HotSpot(TM) 64-Bit Server VM (build 25.0-b70, mixed mode)

OS version: CentOS release 6.8 (Final) Linux 64bit
[root@atom1 jenkins]# cat /etc/redhat-release
CentOS release 6.8 (Final)
[root@atom1 jenkins]# uname -a
Linux atom1 2.6.32-642.11.1.el6.x86_64 #1 SMP Fri Nov 18 19:25:05 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux

Description of the problem including expected versus actual behavior:

Steps to reproduce:

1. Search and scroll using the following query.
   _search/?scroll=1m

{
  "size": 0,
  "query": {
    "constant_score": {
      "filter": {
        "bool": {
          "must": [
            {
              "range": {
                "@timestamp": {
                  "gte" : "now-1d/d",
                  "lt" :  "now/d"
                }
              }
            },
            {
              "exists": {
                "field": "session"
              }
            }
          ]
        }
      }
    }
  },
  "aggs": {
    "2": {
      "terms": {
        "field": "session.id.raw"
      },
      "aggs": {
        "3": {
          "terms": {
            "field": "@timestamp",
            "size": 1,
            "order": {
              "_term": "asc"
            }
          },
          "aggs": {
            "4": {
              "top_hits": {
                "size": 1
              }
            }
          }
        }
      }
    }
  }
}

2. Initial search request is successful. Second search, now with scroll_id as returned in step 1 fails.
   _search/scroll?scroll=1m

{
   "error":{
      "root_cause":[

      ],
      "type":"reduce_search_phase_exception",
      "reason":"[reduce] inner finish failed",
      "phase":"fetch",
      "grouped":true,
      "failed_shards":[

      ],
      "caused_by":{
         "type":"null_pointer_exception",
         "reason":null
      }
   },
   "status":503
}

Cluster health:
[root@atom1 jenkins]# curl -XGET http://localhost:9200/_cluster/health?pretty=true

{
  "cluster_name" : "atomcluster",
  "status" : "green",
  "timed_out" : false,
  "number_of_nodes" : 2,
  "number_of_data_nodes" : 2,
  "active_primary_shards" : 165,
  "active_shards" : 330,
  "relocating_shards" : 0,
  "initializing_shards" : 0,
  "unassigned_shards" : 0,
  "delayed_unassigned_shards" : 0,
  "number_of_pending_tasks" : 0,
  "number_of_in_flight_fetch" : 0,
  "task_max_waiting_in_queue_millis" : 0,
  "active_shards_percent_as_number" : 100.0
}

Cluster log:

[2017-01-09T13:48:06,677][DEBUG][o.e.i.f.p.SortedSetDVOrdinalsIndexFieldData] global-ordinals [session.id.raw][1972] took [3.6ms]
[2017-01-09T13:48:06,779][DEBUG][o.e.i.f.p.SortedSetDVOrdinalsIndexFieldData] global-ordinals [session.id.raw][2017] took [15.5ms]
[2017-01-09T13:48:06,914][WARN ][r.suppressed             ] path: /_search/scroll, params: {scroll=1m}
org.elasticsearch.action.search.ReduceSearchPhaseException: [reduce] inner finish failed
        at org.elasticsearch.action.search.SearchScrollQueryThenFetchAsyncAction.finishHim(SearchScrollQueryThenFetchAsyncAction.java:217) [elasticsearch-5.1.1.jar:5.1.1]
        at org.elasticsearch.action.search.SearchScrollQueryThenFetchAsyncAction.executeFetchPhase(SearchScrollQueryThenFetchAsyncAction.java:175) [elasticsearch-5.1.1.jar:5.1.1]
        at org.elasticsearch.action.search.SearchScrollQueryThenFetchAsyncAction.access$000(SearchScrollQueryThenFetchAsyncAction.java:44) [elasticsearch-5.1.1.jar:5.1.1]
        at org.elasticsearch.action.search.SearchScrollQueryThenFetchAsyncAction$1.onResponse(SearchScrollQueryThenFetchAsyncAction.java:135) [elasticsearch-5.1.1.jar:5.1.1]
        at org.elasticsearch.action.search.SearchScrollQueryThenFetchAsyncAction$1.onResponse(SearchScrollQueryThenFetchAsyncAction.java:129) [elasticsearch-5.1.1.jar:5.1.1]
        at org.elasticsearch.action.ActionListenerResponseHandler.handleResponse(ActionListenerResponseHandler.java:46) [elasticsearch-5.1.1.jar:5.1.1]
        at org.elasticsearch.transport.TransportService$ContextRestoreResponseHandler.handleResponse(TransportService.java:978) [elasticsearch-5.1.1.jar:5.1.1]
        at org.elasticsearch.transport.TcpTransport$1.doRun(TcpTransport.java:1289) [elasticsearch-5.1.1.jar:5.1.1]
        at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37) [elasticsearch-5.1.1.jar:5.1.1]
        at org.elasticsearch.common.util.concurrent.EsExecutors$1.execute(EsExecutors.java:109) [elasticsearch-5.1.1.jar:5.1.1]
        at org.elasticsearch.transport.TcpTransport.handleResponse(TcpTransport.java:1281) [elasticsearch-5.1.1.jar:5.1.1]
        at org.elasticsearch.transport.TcpTransport.messageReceived(TcpTransport.java:1250) [elasticsearch-5.1.1.jar:5.1.1]
        at org.elasticsearch.transport.netty4.Netty4MessageChannelHandler.channelRead(Netty4MessageChannelHandler.java:74) [transport-netty4-5.1.1.jar:5.1.1]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:373) [netty-transport-4.1.6.Final.jar:4.1.6.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:359) [netty-transport-4.1.6.Final.jar:4.1.6.Final]
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:351) [netty-transport-4.1.6.Final.jar:4.1.6.Final]
        at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:293) [netty-codec-4.1.6.Final.jar:4.1.6.Final]
        at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:280) [netty-codec-4.1.6.Final.jar:4.1.6.Final]
        at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:396) [netty-codec-4.1.6.Final.jar:4.1.6.Final]
        at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:248) [netty-codec-4.1.6.Final.jar:4.1.6.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:373) [netty-transport-4.1.6.Final.jar:4.1.6.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:359) [netty-transport-4.1.6.Final.jar:4.1.6.Final]
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:351) [netty-transport-4.1.6.Final.jar:4.1.6.Final]
        at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1334) [netty-transport-4.1.6.Final.jar:4.1.6.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:373) [netty-transport-4.1.6.Final.jar:4.1.6.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:359) [netty-transport-4.1.6.Final.jar:4.1.6.Final]
        at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:926) [netty-transport-4.1.6.Final.jar:4.1.6.Final]
        at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:129) [netty-transport-4.1.6.Final.jar:4.1.6.Final]
        at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:651) [netty-transport-4.1.6.Final.jar:4.1.6.Final]
        at io.netty.channel.nio.NioEventLoop.processSelectedKeysPlain(NioEventLoop.java:536) [netty-transport-4.1.6.Final.jar:4.1.6.Final]
        at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:490) [netty-transport-4.1.6.Final.jar:4.1.6.Final]
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:450) [netty-transport-4.1.6.Final.jar:4.1.6.Final]
        at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:873) [netty-common-4.1.6.Final.jar:4.1.6.Final]
        at java.lang.Thread.run(Thread.java:744) [?:1.8.0]
Caused by: java.lang.NullPointerException

The session field as well as the @timestamp field exists in all documents during the time period of now - 1d.
Is there anything that can be done to fix this? Please let me know what info you would need to help you in solving this issue.

[clintongormley]

Hi @Rogier75

Could you try removing the aggs and see if that resolves the issue? Also, if you're able to provide a set of working documents and mappings etc that reliably trigger this failure, it would be very helpful.

[Rogier75]

I have not yet been able to produce any test data because any new index that I create does not trigger the bug.

What I can see is the following:

Search and scroll with aggregation:
a. Old index with session.id type is string: search is successful, but scroll returns 0 hits.
b. Old index with session.id type is text: search is successful, but scroll gets ReduceSearchPhaseException caused by NullPointerException
c. New index >= 5.0 search and scroll are successful

Search and scroll without aggregation:
Search and scroll without aggregation is successful on both old and new indexes

I now plan to reindex my data and or remove old data.

[clintongormley]

@jpountz any ideas what might be happening here?

[Rogier75]

I was able to reproduce the empty scroll after a successful search. This has worked for me in the past even though mentioned here is:

If the request specifies aggregations, only the initial search response will contain the aggregations results.

To reproduce the empty scroll result on Elasticsearch 5.1.1:

Test data: contains 18 documents with unique session.id
https://gist.github.com/Rogier75/27136d1996dfc50c90c31ad07c75a1e9

Data mapping (generated):
https://gist.github.com/Rogier75/dfe6a6b0bcec81075a880d6090096193

Search query: GET github_22500/_search/?scroll=1m
https://gist.github.com/Rogier75/cd515adc269159ab08b45de29bd3333c

Search result: successfully returns 10 hits
https://gist.github.com/Rogier75/d4c135bfcc0a29b8daf0d27ff9f714eb

Scroll: GET _search/scroll?scroll=1m
DnF1ZXJ5VGhlbkZldGNoAgAAAAAAB7uQFjczYWFZNzVCU2MtSTA0TGQwbkpDaGcAAAAAAAezeBZkSUhyYXI4NVE3S19TX0cwRU9PdDhR

Scroll result: is empty where expected 8 hits

{
   "_scroll_id":"DnF1ZXJ5VGhlbkZldGNoAgAAAAAAB7uQFjczYWFZNzVCU2MtSTA0TGQwbkpDaGcAAAAAAAezeBZkSUhyYXI4NVE3S19TX0cwRU9PdDhR",
   "took":1,
   "timed_out":false,
   "_shards":{
      "total":2,
      "successful":2,
      "failed":0
   },
   "hits":{
      "total":18,
      "max_score":0,
      "hits":[

      ]
   }
}

[jimczi]

I don't understand what you're trying to achieve. If you send a scroll query with size:0 it is expected that you get no hits. In fact with size:0 you are sure that the first query will return no hits and then your scroll is considered as finish.
Regarding the aggregation only the initial query will return result for the aggs, subsequent queries with _scroll will not compute the aggregations. Can you explain why you use size:0 and aggregations in a scroll query ? This is not intended to be used like this so unless you find a reproduction for the NPE I think we can consider that this issue is solved.

[Rogier75]

@jimczi
Please bear with me for one second and let me explain what I'm trying to do. If you tell me that it is impossible than I will implement another solution:

Imagine the following 4 documents exist with a timestamp and session.id:

1. timestamp: 18:50 session.id: 1
2. timestamp: 18:55 session.id: 1
3. timestamp: 19:00 session.id: 2
4. timestamp: 19:05 session.id: 2

I want to search and scroll and want to find one document for each unique session.id but get only the ones with the earliest timestamp. So in the above case I want to get document 1 and 3.

If I remove the size:0 I can scroll further but since there is no aggregated result I don't get the documents that I am querying for.

I guess that it would be best for me to create a separate index to contain only (a duplicate of) those unique documents by session.id with the earliest time stamp. On that index I could then search and scroll without aggregation.