array_index_out_of_bounds_exception when terms agg ordered by top_metrics agg

[drewdaemon]

Elasticsearch Version

8.2

Installed Plugins

No response

Java Version

bundled

OS Version

OSX 11.6

Problem Description

A terms aggregation on a keyword field ordered by a top_metrics aggregation on a date field for a particular time range results in an array_index_out_of_bounds_exception on the Elasticsearch side.

Steps to Reproduce

Add the kibana_sample_data_ecommerce to the cluster (I was using the 8.2 snapshot). Then, run the following query that runs a terms agg ordered by a top_metrics agg.

{
  "aggs": {
    "0": {
      "terms": {
        "field": "customer_first_name.keyword",
        "order": {
          "1-bucket>1-metric[customer_birth_date]": "desc"
        },
        "size": 5
      },
      "aggs": {
        "1-bucket": {
          "filter": {
            "bool": {
              "must": [],
              "filter": [
                {
                  "bool": {
                    "should": [
                      {
                        "exists": {
                          "field": "customer_birth_date"
                        }
                      }
                    ],
                    "minimum_should_match": 1
                  }
                }
              ],
              "should": [],
              "must_not": []
            }
          },
          "aggs": {
            "1-metric": {
              "top_metrics": {
                "metrics": {
                  "field": "customer_birth_date"
                },
                "size": 1,
                "sort": {
                  "order_date": "desc"
                }
              }
            }
          }
        }
      }
    }
  },
  "size": 0,
  "fields": [
    {
      "field": "customer_birth_date",
      "format": "date_time"
    },
    {
      "field": "order_date",
      "format": "date_time"
    },
    {
      "field": "products.created_on",
      "format": "date_time"
    }
  ],
  "script_fields": {},
  "stored_fields": [
    "*"
  ],
  "runtime_mappings": {},
  "_source": {
    "excludes": []
  },
  "query": {
    "bool": {
      "must": [],
      "filter": [
        {
          "range": {
            "order_date": {
              "format": "strict_date_optional_time",
              "gte": "2021-12-03T23:36:40.426Z",
              "lte": "2022-03-18T22:36:40.426Z"
            }
          }
        }
      ],
      "should": [],
      "must_not": []
    }
  }
}

Logs (if relevant)

Response Body

{
  "error" : {
    "root_cause" : [
      {
        "type" : "array_index_out_of_bounds_exception",
        "reason" : "Index 8 out of bounds for length 1"
      }
    ],
    "type" : "search_phase_execution_exception",
    "reason" : "all shards failed",
    "phase" : "query",
    "grouped" : true,
    "failed_shards" : [
      {
        "shard" : 0,
        "index" : "kibana_sample_data_ecommerce",
        "node" : "AS6pXentQHKWbWhGkdGVUQ",
        "reason" : {
          "type" : "array_index_out_of_bounds_exception",
          "reason" : "Index 8 out of bounds for length 1"
        }
      }
    ],
    "caused_by" : {
      "type" : "array_index_out_of_bounds_exception",
      "reason" : "Index 8 out of bounds for length 1",
      "caused_by" : {
        "type" : "array_index_out_of_bounds_exception",
        "reason" : "Index 8 out of bounds for length 1"
      }
    }
  },
  "status" : 500
}

Elasticsearch Logs

path: /kibana_sample_data_ecommerce/_search, params: {pretty=true, index=kibana_sample_data_ecommerce}
org.elasticsearch.action.search.SearchPhaseExecutionException: all shards failed
	at org.elasticsearch.action.search.AbstractSearchAsyncAction.onPhaseFailure(AbstractSearchAsyncAction.java:730) [elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	at org.elasticsearch.action.search.AbstractSearchAsyncAction.executeNextPhase(AbstractSearchAsyncAction.java:417) [elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	at org.elasticsearch.action.search.AbstractSearchAsyncAction.onPhaseDone(AbstractSearchAsyncAction.java:762) [elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	at org.elasticsearch.action.search.AbstractSearchAsyncAction.onShardFailure(AbstractSearchAsyncAction.java:514) [elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	at org.elasticsearch.action.search.AbstractSearchAsyncAction$1.onFailure(AbstractSearchAsyncAction.java:348) [elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	at org.elasticsearch.action.ActionListener$Delegating.onFailure(ActionListener.java:66) [elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	at org.elasticsearch.action.ActionListenerResponseHandler.handleException(ActionListenerResponseHandler.java:48) [elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	at org.elasticsearch.action.search.SearchTransportService$ConnectionCountingHandler.handleException(SearchTransportService.java:651) [elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	at org.elasticsearch.transport.TransportService$4.handleException(TransportService.java:724) [elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	at org.elasticsearch.transport.TransportService$ContextRestoreResponseHandler.handleException(TransportService.java:1349) [elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	at org.elasticsearch.transport.TransportService$DirectResponseChannel.processException(TransportService.java:1458) [elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	at org.elasticsearch.transport.TransportService$DirectResponseChannel.sendResponse(TransportService.java:1432) [elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	at org.elasticsearch.transport.TaskTransportChannel.sendResponse(TaskTransportChannel.java:50) [elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	at org.elasticsearch.action.support.ChannelActionListener.onFailure(ChannelActionListener.java:47) [elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	at org.elasticsearch.action.ActionRunnable.onFailure(ActionRunnable.java:77) [elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:28) [elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	at org.elasticsearch.common.util.concurrent.TimedRunnable.doRun(TimedRunnable.java:33) [elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:773) [elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:26) [elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
	at java.lang.Thread.run(Thread.java:833) [?:?]
Caused by: org.elasticsearch.ElasticsearchException$1: Index 8 out of bounds for length 1
	at org.elasticsearch.ElasticsearchException.guessRootCauses(ElasticsearchException.java:638) ~[elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	at org.elasticsearch.action.search.AbstractSearchAsyncAction.executeNextPhase(AbstractSearchAsyncAction.java:415) [elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	... 20 more
Caused by: java.lang.ArrayIndexOutOfBoundsException: Index 8 out of bounds for length 1
	at jdk.internal.util.Preconditions$1.apply(Preconditions.java:177) ~[?:?]
	at jdk.internal.util.Preconditions$1.apply(Preconditions.java:174) ~[?:?]
	at jdk.internal.util.Preconditions.outOfBounds(Preconditions.java:62) ~[?:?]
	at jdk.internal.util.Preconditions.outOfBoundsCheckIndex(Preconditions.java:70) ~[?:?]
	at jdk.internal.util.Preconditions.checkIndex(Preconditions.java:266) ~[?:?]
	at java.lang.invoke.VarHandleByteArrayAsLongs$ArrayHandle.index(VarHandleByteArrayAsLongs.java:103) ~[?:?]
	at java.lang.invoke.VarHandleByteArrayAsLongs$ArrayHandle.get(VarHandleByteArrayAsLongs.java:120) ~[?:?]
	at org.elasticsearch.common.util.BigArrays$ByteArrayAsLongArrayWrapper.get(BigArrays.java:224) ~[elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	at org.elasticsearch.xpack.analytics.topmetrics.TopMetricsAggregator$LongMetricValues.doubleValue(TopMetricsAggregator.java:363) ~[?:?]
	at org.elasticsearch.xpack.analytics.topmetrics.TopMetricsAggregator$Metrics.metric(TopMetricsAggregator.java:177) ~[?:?]
	at org.elasticsearch.xpack.analytics.topmetrics.TopMetricsAggregator.metric(TopMetricsAggregator.java:113) ~[?:?]
	at org.elasticsearch.search.aggregations.metrics.NumericMetricsAggregator$MultiValue.lambda$bucketComparator$0(NumericMetricsAggregator.java:64) ~[elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	at org.elasticsearch.search.aggregations.InternalOrder$Aggregation.lambda$partiallyBuiltBucketComparator$0(InternalOrder.java:68) ~[elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	at org.elasticsearch.search.aggregations.InternalOrder$CompoundOrder.lambda$partiallyBuiltBucketComparator$1(InternalOrder.java:192) ~[elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	at org.elasticsearch.search.aggregations.bucket.terms.BucketPriorityQueue.lessThan(BucketPriorityQueue.java:25) ~[elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	at org.apache.lucene.util.PriorityQueue.upHeap(PriorityQueue.java:245) ~[lucene-core-9.1.0-snapshot-5b522487ba8.jar:9.1.0-snapshot-5b522487ba8 5b522487ba8e0f1002b50a136817ca037aec9686 - jenkins - 2022-03-16 13:04:11]
	at org.apache.lucene.util.PriorityQueue.add(PriorityQueue.java:129) ~[lucene-core-9.1.0-snapshot-5b522487ba8.jar:9.1.0-snapshot-5b522487ba8 5b522487ba8e0f1002b50a136817ca037aec9686 - jenkins - 2022-03-16 13:04:11]
	at org.apache.lucene.util.PriorityQueue.insertWithOverflow(PriorityQueue.java:142) ~[lucene-core-9.1.0-snapshot-5b522487ba8.jar:9.1.0-snapshot-5b522487ba8 5b522487ba8e0f1002b50a136817ca037aec9686 - jenkins - 2022-03-16 13:04:11]
	at org.elasticsearch.search.aggregations.bucket.terms.GlobalOrdinalsStringTermsAggregator$ResultStrategy$1.accept(GlobalOrdinalsStringTermsAggregator.java:613) ~[elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	at org.elasticsearch.search.aggregations.bucket.terms.GlobalOrdinalsStringTermsAggregator$RemapGlobalOrds.forEach(GlobalOrdinalsStringTermsAggregator.java:561) ~[elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	at org.elasticsearch.search.aggregations.bucket.terms.GlobalOrdinalsStringTermsAggregator$ResultStrategy.buildAggregations(GlobalOrdinalsStringTermsAggregator.java:602) ~[elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	at org.elasticsearch.search.aggregations.bucket.terms.GlobalOrdinalsStringTermsAggregator.buildAggregations(GlobalOrdinalsStringTermsAggregator.java:182) ~[elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	at org.elasticsearch.search.aggregations.Aggregator.buildTopLevel(Aggregator.java:154) ~[elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	at org.elasticsearch.search.aggregations.AggregationPhase.execute(AggregationPhase.java:112) ~[elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	at org.elasticsearch.search.query.QueryPhase.execute(QueryPhase.java:94) ~[elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	at org.elasticsearch.indices.IndicesService.lambda$loadIntoContext$27(IndicesService.java:1516) ~[elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	at org.elasticsearch.indices.IndicesService.lambda$cacheShardLevelResult$28(IndicesService.java:1582) ~[elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	at org.elasticsearch.indices.IndicesRequestCache$Loader.load(IndicesRequestCache.java:178) ~[elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	at org.elast
icsearch.indices.IndicesRequestCache$Loader.load(IndicesRequestCache.java:161) ~[elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	at org.elasticsearch.common.cache.Cache.computeIfAbsent(Cache.java:418) ~[elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	at org.elasticsearch.indices.IndicesRequestCache.getOrCompute(IndicesRequestCache.java:124) ~[elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	at org.elasticsearch.indices.IndicesService.cacheShardLevelResult(IndicesService.java:1588) ~[elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	at org.elasticsearch.indices.IndicesService.loadIntoContext(IndicesService.java:1510) ~[elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	at org.elasticsearch.search.SearchService.loadOrExecuteQueryPhase(SearchService.java:460) ~[elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	at org.elasticsearch.search.SearchService.executeQueryPhase(SearchService.java:625) ~[elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	at org.elasticsearch.search.SearchService.lambda$executeQueryPhase$2(SearchService.java:487) ~[elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	at org.elasticsearch.action.ActionRunnable.lambda$supply$0(ActionRunnable.java:47) ~[elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	at org.elasticsearch.action.ActionRunnable$2.doRun(ActionRunnable.java:62) ~[elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]
	at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:26) ~[elasticsearch-8.2.0-SNAPSHOT.jar:8.2.0-SNAPSHOT]

[elasticmachine]

Pinging @elastic/es-analytics-geo (Team:Analytics)

[nik9000]

@salvatore-campagna this is in code that you are working on for the keyword comparison. It looks like a missing bounds check on the saved buckets. Are you interested in having a look?

[salvatore-campagna]

@nik9000 I can have a look at it.

[salvatore-campagna]

I tried the following YAML test against Elasticsearch master without being able to reproduce the issue. Maybe I need data that resembles more the actual data?

setup:
  - do:
      indices.create:
        index: test
        body:
          settings:
            number_of_replicas: 0
          mappings:
            properties:
              name:
                type: keyword
              birth_date:
                type: date
              order_date:
                type: date


  - do:
      bulk:
        index: test
        refresh: true
        body:
          - { "index": {} }
          - { "name": "alice", "birth_date": "1990-06-05T19:20:01.000Z", "order_date": "2021-09-09T17:50:00.000Z" }
          - { "index": { } }
          - { "name": "bob", "birth_date": "1989-03-04T22:10:00.000Z", "order_date": "2021-10-12T18:39:00.000Z" }
          - { "index": { } }
          - { "name": "charlie", "birth_date": "1991-07-02T:18:17:00.000Z", "order_date": "2021-12-10T19:33:00.000Z" }
          - { "index": { } }
          - { "name": "david", "order_date": "2021-08-09T17:22:00.000Z" }
          - { "index": { } }
          - { "name": "erika", "birth_date": "1992-12-11T12:13:00.000Z", "order_date": "2021-09-02T16:44:00.000Z" }
          - { "index": { } }
          - { "name": "mike", "birth_date": "1988-01-20T13:24:00.000Z", "order_date": "2021-11-11T15:22:00.000Z" }
          - { "index": { } }
          - { "name": "tony", "order_date": "2021-08-11T18:11:00.000Z" }
          - { "index": { } }
          - { "name": "paul", "birth_date": "1989-11-07T14:22:00.000Z", "order_date": "2021-08-29T18:47:00.000Z" }
          - { "index": { } }
          - { "name": "alice", "birth_date": "1990-06-05T19:20:01.000Z", "order_date": "2021-08-11T17:22:00.000Z" }
          - { "index": { } }
          - { "name": "charlie", "birth_date": "1991-07-02T:18:17:00.000Z", "order_date": "2021-11-22T18:47:00.000Z" }
          - { "index": { } }
          - { "name": "charlie", "birth_date": "1991-07-02T:18:17:00.000Z", "order_date": "2021-08-10T18:31:00.000Z" }
          - { "index": { } }
          - { "name": "david", "birth_date": "2021-08-09T17:22:00.000Z", "order_date": "2021-11-09T17:29:00.000Z" }
          - { "index": { } }
          - { "name": "erika", "order_date": "1992-12-11T12:13:00.000Z" }
          - { "index": { } }
          - { "name": "david", "order_date": "2021-08-09T17:22:00.000Z" }
          - { "index": { } }
          - { "name": "tony", "birth_date": "2021-08-11T18:11:00.000Z", "order_date": "2021-09-27T18:29:00.000Z" }
          - { "index": { } }
          - { "name": "erika", "birth_date": "1992-12-11T12:13:00.000Z", "order_date": "2021-10-24T18:37:00.000Z" }

---
"terms order by top metrics":
  - skip:
      version: " - 8.1.99"
      reason: bug in 8.2.0
  - do:
      search:
        body:
          query:
            bool:
              filter:
                - range:
                    order_date:
                      format: strict_date_optional_time
                      gte: "2021-01-01T10:00:00.000Z"
                      lte: "2021-12-31T10:00:00.000Z"
          size: 0
          aggs:
            name:
              terms:
                field: name
                order:
                  "birth_date_exists>top_birth_date[birth_date]": desc
                size: 5
              aggs:
                birth_date_exists:
                  filter:
                    bool:
                      filter:
                        - bool:
                            should:
                              - exists:
                                  field: birth_date
                            minimum_should_match: 1
                  aggs:
                    top_birth_date:
                      top_metrics:
                        metrics:
                          field: birth_date
                        size: 1
                        sort:
                          "order_date": desc

  - match: { hits.total.value: 12 }

[salvatore-campagna]

@andrewctate If I understand correctly the order_date is modified by Kibana so to update it and not forcing the user go back in time to look at data. Would you be able to point us to the code doing that manipulation? At the moment, with raw data taken from https://github.com/elastic/kibana/tree/main/src/plugins/home/server/services/sample_data/data_sets/ecommerce
I am not able to reproduce the issue and would like to see if applying the same manipulation something changes.

[drewdaemon]

@salvatore-campagna thanks for looking into this.

It looks like the timestamp transformation is defined here called from here.

If there's a way to provide you with the exact dataset from my local cluster, I'm happy to do so as well.

[salvatore-campagna]

@andrewctate I have just noticed using a cluster in the cloud and the sample dataset that queries like the following two queries return no data for customer_birth_date field. As you can see I just get back a single bucket whose key is the value I used for the missing property in the first one. So, it looks like no document in the index has a non-null customer_birth_date. In the second one there is no result at all because of the filter which results in the top metrics not running at all.

GET /kibana_sample_data_ecommerce/_search
{
  "size": 0,
  "aggs": {
    "birth_dates": {
      "date_histogram": {
        "field": "customer_birth_date",
        "calendar_interval": "day",
        "missing": "1970-01-01"
      }
    }
  }
}

GET /kibana_sample_data_ecommerce/_search
{
  "size": 0,
  "aggs": {
    "1-bucket": {
      "filter": {
        "bool": {
          "must": [],
          "filter": [
            {
              "bool": {
                "should": [
                  {
                    "exists": {
                      "field": "customer_birth_date"
                    }
                  }
                ],
                "minimum_should_match": 1
              }
            }
          ],
          "should": [],
          "must_not": []
        }
      },
      "aggs": {
        "birth_dates": {
          "date_histogram": {
            "field": "customer_birth_date",
            "calendar_interval": "day",
            "missing": "1970-01-01"
          }
        }
      }
    }
  }
}

NOTE: I agree that we might not want to throw an exception and that we might handle that specific case but something looks wrong to me.

[drewdaemon]

@salvatore-campagna this query was generated by Kibana Lens and the query itself is valid, right?

Returning no results is fine since that is understandable to the user. However, they are currently exposed to the 500 status error with a non-helpful (from a user's perspective) explanation. This is a sub-optimal experience we should improve if possible.