Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

date_histogram parse_exception in time_zone America/Phoenix #50265

Closed
kertal opened this issue Dec 17, 2019 · 2 comments · Fixed by #52016
Closed

date_histogram parse_exception in time_zone America/Phoenix #50265

kertal opened this issue Dec 17, 2019 · 2 comments · Fixed by #52016
Assignees

Comments

@kertal
Copy link
Member

kertal commented Dec 17, 2019

Elasticsearch version (bin/elasticsearch --version): 8.0.0-SNAPSHOT

Plugins installed: []

JVM version (java -version): 13.0.1

OS version (uname -a if on a Unix-like system): Darwin Kernel Version 18.7.0

Description of the problem including expected versus actual behavior:

A date_histogram with a fixed_interval range of 1ms to 999ms in the timezone America/Phoenix causes a "parse_exception". In other timezones e.g. Europe/Berlin it works

Steps to reproduce:

  1. Try the following request when you've got our Kibana sample flight test data installed
GET kibana_sample_data_flights/_search
{
  "aggs": {
    "2": {
      "date_histogram": {
        "field": "timestamp",
        "fixed_interval": "1ms",
        "time_zone": "America/Phoenix",
        "min_doc_count": 1
      }
    }
  }
}

Here's the error message of the result:

{
  "error" : {
    "root_cause" : [
      {
        "type" : "parse_exception",
        "reason" : "failed to parse date field [-68659199999] with format [epoch_millis]: [failed to parse date field [-68659199999] with format [epoch_millis]]"
      }
    ],
    "type" : "search_phase_execution_exception",
    "reason" : "all shards failed",
    "phase" : "query",
    "grouped" : true,
    "failed_shards" : [
      {
        "shard" : 0,
        "index" : "kibana_sample_data_flights",
        "node" : "N2J6g-DxSySnU5YiP-9aAA",
        "reason" : {
          "type" : "parse_exception",
          "reason" : "failed to parse date field [-68659199999] with format [epoch_millis]: [failed to parse date field [-68659199999] with format [epoch_millis]]",
          "caused_by" : {
            "type" : "illegal_argument_exception",
            "reason" : "failed to parse date field [-68659199999] with format [epoch_millis]",
            "caused_by" : {
              "type" : "date_time_parse_exception",
              "reason" : "Failed to parse with all enclosed parsers"
            }
          }
        }
      }
    ]
  },
  "status" : 400
}

Provide logs (if relevant):

   │ info [o.e.a.s.TransportSearchAction] [kertal-elastic.local] All shards failed for phase: [query]
   │      org.elasticsearch.ElasticsearchParseException: failed to parse date field [-68659199001] with format [epoch_millis]: [failed to parse date field [-68659199001] with format [epoch_millis]]
   │      	at org.elasticsearch.common.time.JavaDateMathParser.parseDateTime(JavaDateMathParser.java:233) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
   │      	at org.elasticsearch.common.time.JavaDateMathParser.parse(JavaDateMathParser.java:74) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
   │      	at org.elasticsearch.index.mapper.DateFieldMapper$DateFieldType.parseToLong(DateFieldMapper.java:401) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
   │      	at org.elasticsearch.index.mapper.DateFieldMapper$DateFieldType.isFieldWithinQuery(DateFieldMapper.java:415) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
   │      	at org.elasticsearch.search.aggregations.bucket.histogram.DateHistogramAggregationBuilder.rewriteTimeZone(DateHistogramAggregationBuilder.java:473) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
   │      	at org.elasticsearch.search.aggregations.bucket.histogram.DateHistogramAggregationBuilder.innerBuild(DateHistogramAggregationBuilder.java:493) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
   │      	at org.elasticsearch.search.aggregations.support.ValuesSourceAggregationBuilder.doBuild(ValuesSourceAggregationBuilder.java:313) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
   │      	at org.elasticsearch.search.aggregations.support.ValuesSourceAggregationBuilder.doBuild(ValuesSourceAggregationBuilder.java:37) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
   │      	at org.elasticsearch.search.aggregations.AbstractAggregationBuilder.build(AbstractAggregationBuilder.java:139) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
   │      	at org.elasticsearch.search.aggregations.AggregatorFactories$Builder.build(AggregatorFactories.java:333) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
   │      	at org.elasticsearch.search.SearchService.parseSource(SearchService.java:790) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
   │      	at org.elasticsearch.search.SearchService.createContext(SearchService.java:586) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
   │      	at org.elasticsearch.search.SearchService.createAndPutContext(SearchService.java:545) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
   │      	at org.elasticsearch.search.SearchService.executeQueryPhase(SearchService.java:348) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
   │      	at org.elasticsearch.search.SearchService.lambda$executeQueryPhase$1(SearchService.java:340) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
   │      	at org.elasticsearch.action.ActionListener.lambda$map$2(ActionListener.java:146) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
   │      	at org.elasticsearch.action.ActionListener$1.onResponse(ActionListener.java:63) [elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
   │      	at org.elasticsearch.action.ActionRunnable.lambda$supply$0(ActionRunnable.java:58) [elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
   │      	at org.elasticsearch.action.ActionRunnable$2.doRun(ActionRunnable.java:73) [elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
   │      	at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37) [elastic
   │ info search-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
   │      	at org.elasticsearch.common.util.concurrent.TimedRunnable.doRun(TimedRunnable.java:44) [elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
   │      	at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:769) [elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
   │      	at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37) [elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
   │      	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
   │      	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
   │      	at java.lang.Thread.run(Thread.java:830) [?:?]
   │      Caused by: java.lang.IllegalArgumentException: failed to parse date field [-68659199001] with format [epoch_millis]
   │      	at org.elasticsearch.common.time.JavaDateFormatter.parse(JavaDateFormatter.java:169) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
   │      	at org.elasticsearch.common.time.JavaDateMathParser.parseDateTime(JavaDateMathParser.java:223) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
   │      	... 25 more
   │      Caused by: java.time.format.DateTimeParseException: Failed to parse with all enclosed parsers
   │      	at org.elasticsearch.common.time.JavaDateFormatter.doParse(JavaDateFormatter.java:196) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
   │      	at org.elasticsearch.common.time.JavaDateFormatter.parse(JavaDateFormatter.java:167) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
   │      	at org.elasticsearch.common.time.JavaDateMathParser.parseDateTime(JavaDateMathParser.java:223) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
   │      	... 25 more
@elasticmachine
Copy link
Collaborator

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

@immavalls
Copy link
Contributor

We've reproduced this with timezone Africa/Johannesburg with the following query that one of the Kibana metricbeat visualizations is building.

Changing to "interval": "1ms" also throws an error. Starting with 1s it works.

Changing to zone Africa/Cairo works with 1ms.

GET metricbeat-*/_search
{
  "size": 0, 
  "aggs": {
    "2": {
      "date_histogram": {
        "field": "@timestamp",
        "fixed_interval": "1ms",
        "time_zone": "Africa/Johannesburg",
        "min_doc_count": 1
      },
      "aggs": {
        "3": {
          "terms": {
            "field": "host.name",
            "order": {
              "1": "desc"
            },
            "size": 20
          },
          "aggs": {
            "1": {
              "avg": {
                "field": "system.cpu.user.norm.pct"
              }
            }
          }
        }
      }
    }
  }
}
{
  "error": {
    "root_cause": [
      {
        "type": "parse_exception",
        "reason": "failed to parse date field [-813805199999] with format [epoch_millis]: [failed to parse date field [-813805199999] with format [epoch_millis]]"
      }
    ],
    "type": "search_phase_execution_exception",
    "reason": "all shards failed",
    "phase": "query",
    "grouped": true,
    "failed_shards": [
      {
        "shard": 0,
        "index": "metricbeat-7.5.2-2020.01.31",
        "node": "dYGZVMFMRPCT7h2v8bothg",
        "reason": {
          "type": "parse_exception",
          "reason": "failed to parse date field [-813805199999] with format [epoch_millis]: [failed to parse date field [-813805199999] with format [epoch_millis]]",
          "caused_by": {
            "type": "illegal_argument_exception",
            "reason": "failed to parse date field [-813805199999] with format [epoch_millis]",
            "caused_by": {
              "type": "date_time_parse_exception",
              "reason": "date_time_parse_exception: Failed to parse with all enclosed parsers"
            }
          }
        }
      }
    ]
  },
  "status": 400
}

@nik9000 nik9000 assigned nik9000 and unassigned jimczi Feb 6, 2020
nik9000 added a commit to nik9000/elasticsearch that referenced this issue Feb 6, 2020
When `date_histogram` attempts to optimize itself it for a particular
time zone it checks to see if the entire shard is within the same
"transition". Most time zone transition once every size months or
thereabouts so the optimization can usually kicks in.

*But* it crashes when you attempt feed it a time zone who's last DST
transition was before epoch. The reason for this is a little twisted:
before this patch it'd find the next and previous transitions in
milliseconds since epoch. Then it'd cast them to `Long`s and pass them
into the `DateFieldType` to check if the shard's contents were within
the range. The trouble is they are then converted to `String`s which are
*then* parsed back to `Instant`s which are then convertd to `long`s. And
the parser doesn't like most negative numbers. And everything before
epoch is negative.

This change removes the
`long` -> `Long` -> `String` -> `Instant` -> `long` chain in favor of
passing the `long`s directly into the `DateFieldType`. Sadly, this means
that `MappedFieldType` gets a `long` specialized implementation of
`isFieldWithinQuery` which is a little lame, but given that we always
call it with a long in this context it feels like the lesser of two
evils. Not because it is more efficient. It is a little. No. This is the
less evil way to solve this problem because it is less confusing to
trace the execution. The parsing code is fairly complex and we can just
skip it entirely because we already *have* longs.

Closes elastic#50265
nik9000 added a commit that referenced this issue Feb 11, 2020
When `date_histogram` attempts to optimize itself it for a particular
time zone it checks to see if the entire shard is within the same
"transition". Most time zone transition once every size months or
thereabouts so the optimization can usually kicks in.

*But* it crashes when you attempt feed it a time zone who's last DST
transition was before epoch. The reason for this is a little twisted:
before this patch it'd find the next and previous transitions in
milliseconds since epoch. Then it'd cast them to `Long`s and pass them
into the `DateFieldType` to check if the shard's contents were within
the range. The trouble is they are then converted to `String`s which are
*then* parsed back to `Instant`s which are then convertd to `long`s. And
the parser doesn't like most negative numbers. And everything before
epoch is negative.

This change removes the
`long` -> `Long` -> `String` -> `Instant` -> `long` chain in favor of
passing the `long` -> `Instant` -> `long` which avoids the fairly complex
parsing code and handles a bunch of interesting edge cases around
epoch. And other edge cases around `date_nanos`.

Closes #50265
nik9000 added a commit to nik9000/elasticsearch that referenced this issue Feb 11, 2020
When `date_histogram` attempts to optimize itself it for a particular
time zone it checks to see if the entire shard is within the same
"transition". Most time zone transition once every size months or
thereabouts so the optimization can usually kicks in.

*But* it crashes when you attempt feed it a time zone who's last DST
transition was before epoch. The reason for this is a little twisted:
before this patch it'd find the next and previous transitions in
milliseconds since epoch. Then it'd cast them to `Long`s and pass them
into the `DateFieldType` to check if the shard's contents were within
the range. The trouble is they are then converted to `String`s which are
*then* parsed back to `Instant`s which are then convertd to `long`s. And
the parser doesn't like most negative numbers. And everything before
epoch is negative.

This change removes the
`long` -> `Long` -> `String` -> `Instant` -> `long` chain in favor of
passing the `long` -> `Instant` -> `long` which avoids the fairly complex
parsing code and handles a bunch of interesting edge cases around
epoch. And other edge cases around `date_nanos`.

Closes elastic#50265
nik9000 added a commit that referenced this issue Feb 12, 2020
When `date_histogram` attempts to optimize itself it for a particular
time zone it checks to see if the entire shard is within the same
"transition". Most time zone transition once every size months or
thereabouts so the optimization can usually kicks in.

*But* it crashes when you attempt feed it a time zone who's last DST
transition was before epoch. The reason for this is a little twisted:
before this patch it'd find the next and previous transitions in
milliseconds since epoch. Then it'd cast them to `Long`s and pass them
into the `DateFieldType` to check if the shard's contents were within
the range. The trouble is they are then converted to `String`s which are
*then* parsed back to `Instant`s which are then convertd to `long`s. And
the parser doesn't like most negative numbers. And everything before
epoch is negative.

This change removes the
`long` -> `Long` -> `String` -> `Instant` -> `long` chain in favor of
passing the `long` -> `Instant` -> `long` which avoids the fairly complex
parsing code and handles a bunch of interesting edge cases around
epoch. And other edge cases around `date_nanos`.

Closes #50265
nik9000 added a commit to nik9000/elasticsearch that referenced this issue Feb 12, 2020
When `date_histogram` attempts to optimize itself it for a particular
time zone it checks to see if the entire shard is within the same
"transition". Most time zone transition once every size months or
thereabouts so the optimization can usually kicks in.

*But* it crashes when you attempt feed it a time zone who's last DST
transition was before epoch. The reason for this is a little twisted:
before this patch it'd find the next and previous transitions in
milliseconds since epoch. Then it'd cast them to `Long`s and pass them
into the `DateFieldType` to check if the shard's contents were within
the range. The trouble is they are then converted to `String`s which are
*then* parsed back to `Instant`s which are then convertd to `long`s. And
the parser doesn't like most negative numbers. And everything before
epoch is negative.

This change removes the
`long` -> `Long` -> `String` -> `Instant` -> `long` chain in favor of
passing the `long` -> `Instant` -> `long` which avoids the fairly complex
parsing code and handles a bunch of interesting edge cases around
epoch. And other edge cases around `date_nanos`.

Closes elastic#50265
nik9000 added a commit that referenced this issue Feb 13, 2020
When `date_histogram` attempts to optimize itself it for a particular
time zone it checks to see if the entire shard is within the same
"transition". Most time zone transition once every size months or
thereabouts so the optimization can usually kicks in.

*But* it crashes when you attempt feed it a time zone who's last DST
transition was before epoch. The reason for this is a little twisted:
before this patch it'd find the next and previous transitions in
milliseconds since epoch. Then it'd cast them to `Long`s and pass them
into the `DateFieldType` to check if the shard's contents were within
the range. The trouble is they are then converted to `String`s which are
*then* parsed back to `Instant`s which are then convertd to `long`s. And
the parser doesn't like most negative numbers. And everything before
epoch is negative.

This change removes the
`long` -> `Long` -> `String` -> `Instant` -> `long` chain in favor of
passing the `long` -> `Instant` -> `long` which avoids the fairly complex
parsing code and handles a bunch of interesting edge cases around
epoch. And other edge cases around `date_nanos`.

Closes #50265
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging a pull request may close this issue.

5 participants