Scripting error "dynamic method [org.joda.time.DateTime, toInstant/0] not found"

[icalvete]

Elasticsearch version (bin/elasticsearch --version):
7.6.1

Plugins installed: []

JVM version (java -version):
openjdk 13.0.2 2020-01-14

OS version (uname -a if on a Unix-like system):
Ubuntu 18.04.3 LTS

Description of the problem including expected versus actual behavior:

{
  "error" : {
    "root_cause" : [ ],
    "type" : "search_phase_execution_exception",
    "reason" : "",
    "phase" : "fetch",
    "grouped" : true,
    "failed_shards" : [ ],
    "caused_by" : {
      "type" : "script_exception",
      "reason" : "runtime error",
      "script_stack" : [
        "(a, b) -> (int) a.timestamp.toInstant().toEpochMilli() - (int) b.timestamp.toInstant().toEpochMilli() ).collect(Collectors.toList()); /* CALCULAMOS LAS SESIONES DE ENVIO DE DATOS */ def ",
        "                           ^---- HERE"
      ],
      "script" : "build_user_sessions_reduce_script",
      "lang" : "painless",
      "caused_by" : {
        "type" : "illegal_argument_exception",
        "reason" : "dynamic method [org.joda.time.DateTime, toInstant/0] not found"
      }
    }
  },
  "status" : 400
}

I read some info related.

#35913
8264326#diff-7a890307c61fef9c84ca1e75a4ba7639

Am i doing something wrong or is that a bug?

Thanks.

[elasticmachine]

Pinging @elastic/es-core-infra (:Core/Infra/Scripting)

[rjernst]

I don't think this is a general scripting issue. It looks like something in watcher is passing through a DateTime object, when it should be a JodaCompatibleZonedDateTime, since we should no longer be exposing joda objects directly anywhere.

There is some weirdness related to the linked issue in that I can't find that whitelist file anywhere in master/7.x. @pgomulka can you take a look?

[pgomulka]

@icalvete can you please provide me with more details on how to reproduce this? Is this a script running from a watcher?

[pgomulka]

@icalvete also can you confirm if data used here was created in 6 before upgrading to 7?
can you share mappings?

[icalvete]

@pgomulka,

This a piece of the script...

`
def data = [:];
data.timestamp = doc['@timestamp'].value;
state.all_queries.add(data);

a.timestamp.toInstant().toEpochMilli()
`

This is @timestamp mapping.

"@timestamp":{"type":"date"}

You are rigth. The indexes were created by 6.

[pgomulka]

@icalvete can you elaborate a bit more on the script? How do you use it? in a watcher? in a search?
can you provide full requests that fail?

[pgomulka]

@icalvete in order to debug this issue we're gonna need some more information.
Can you provide a full reproduction of the issue.
Script snippets are not nearly as helpful.
For example, the failure occurred in your original report when a.timestamp.toInstant() is called. However, that call is in a lambda and we don't see where that lambda is used.
It seems like this is a pretty involved watcher script. If you'd prefer to create a different, shorter script that results in the same error, that would be helpful.
We'd like to see the script and the mappings of the fields used in the script.

[icalvete]

We fixit.

def data = [:];
data.timestamp = doc['@timestamp'].value;
state.all_queries.add(data);

a.timestamp.toInstant().toEpochMilli()

We cast the @timestamp field to (ZonedDateTime)

def data = [:];
data.timestamp = (ZonedDateTime) doc['@timestamp'].value;
state.all_queries.add(data);

a.timestamp.toInstant().toEpochMilli()

Thanks.

[pgomulka]

hey @icalvete this is really surprising that it fixed the problem.
can you please share the requests that you use for these scripts?
I am trying to guess, would it be a scripted metric aggregation within watcher's input search?
https://www.elastic.co/guide/en/elasticsearch/reference/7.6/search-aggregations-metrics-scripted-metric-aggregation.html

[icalvete]

You can reproduce the issue (at least in our environment, with our data) in a scripted metric computed in a query.

We have a mapping like this for the index "my_index":

{"my_index":{"aliases":{},"mappings":{"properties":{"@timestamp":{"type":"date"}}}}  

The following query

GET my_index/_search
{
  "query" : {    
    "match_all": {}
  },
  "aggs": {
    "my_metric": {
      "scripted_metric": {
        "init_script": """
state.all_timestamps = []
""",
        "map_script": """
state.all_timestamps.add(doc['@timestamp'].value)
""",
        "combine_script": """
def all_timestamps = []; 
all_timestamps.addAll(state.all_timestamps); 
return all_timestamps;
""",
        "reduce_script": """
def all_timestamps = []; 
for (state in states) { 
 all_timestamps.addAll(state); 
} 
def all_epochs = [];
for (timestamp in all_timestamps) {
  all_epochs.add(timestamp);
}
return all_epochs;
"""
      }
    }
  }    
}

...returns a list of dates, as expected:

  "aggregations" : {
    "my_metric" : {
      "value" : [
        "2020-02-17T10:49:02.525Z",
        "2020-02-17T12:03:51.810Z",
        "2020-02-17T11:11:50.607Z",
        "2020-02-17T10:39:14.422Z",
        "2020-02-17T13:10:11.378Z",
        "2020-02-17T21:20:22.191Z",
        "2020-02-17T21:24:54.937Z",
        "2020-02-17T21:00:27.707Z"
      ]
    }
  }

But if we try instead to return a list of epoch values (adding .toInstant().toEpochMilli()):

GET my_index/_search
{
  "query" : {    
    "match_all": {}
  },
  "aggs": {
    "my_metric": {
      "scripted_metric": {
        "init_script": """
state.all_timestamps = []
""",
        "map_script": """
state.all_timestamps.add(doc['@timestamp'].value)
""",
        "combine_script": """
def all_timestamps = []; 
all_timestamps.addAll(state.all_timestamps); 
return all_timestamps;
""",
        "reduce_script": """
def all_timestamps = []; 
for (state in states) { 
 all_timestamps.addAll(state); 
} 
def all_epochs = [];
for (timestamp in all_timestamps) {
  all_epochs.add(timestamp.toInstant().toEpochMilli());
}
return all_epochs;
"""
      }
    }
  }    
}

... then it fails:

{
  "error" : {
    "root_cause" : [ ],
    "type" : "search_phase_execution_exception",
    "reason" : "",
    "phase" : "fetch",
    "grouped" : true,
    "failed_shards" : [ ],
    "caused_by" : {
      "type" : "script_exception",
      "reason" : "runtime error",
      "script_stack" : [
        "all_epochs.add(timestamp.toInstant().toEpochMilli());\n}\n",
        "                        ^---- HERE"
      ],
      "script" : "\ndef all_timestamps = []; \nfor (state in states) { \n all_timestamps.addAll(state); \n} \ndef all_epochs = [];\nfor (timestamp in all_timestamps) {\n  all_epochs.add(timestamp.toInstant().toEpochMilli());\n}\nreturn all_epochs;\n",
      "lang" : "painless",
      "caused_by" : {
        "type" : "illegal_argument_exception",
        "reason" : "dynamic method [org.joda.time.DateTime, toInstant/0] not found"
      }
    }
  },
  "status" : 400
}

If we cast to ZonedDateTime in the map_script:

GET my_index/_search
{
  "query" : {    
    "match_all": {}
  },
  "aggs": {
    "my_metric": {
      "scripted_metric": {
        "init_script": """
state.all_timestamps = []
""",
        "map_script": """
state.all_timestamps.add((ZonedDateTime)doc['@timestamp'].value);
""",
        "combine_script": """
def all_timestamps = []; 
all_timestamps.addAll(state.all_timestamps); 
return all_timestamps;
""",
        "reduce_script": """
def all_timestamps = []; 
for (state in states) { 
 all_timestamps.addAll(state); 
} 
def all_epochs = [];
for (timestamp in all_timestamps) {
  all_epochs.add(timestamp.toInstant().toEpochMilli());
}
return all_epochs;
"""
      }
    }
  }    
}

... then it works as expected and returns the epoch millis array.

  "aggregations" : {
    "my_metric" : {
      "value" : [
        1581964030728,
        1581956659329,
        1581957308138,
        1581964611556,
        1581955771685,
        1581934346308,
        1581953299686,
        1581950242461,
        1581949832673,
1581979315992,
        1581915417735,
        1581923812498
      ]
    }
  }

Apparently during the map_script the underlying object is being casted to a org.joda.time.DateTime and forcing an explicit cast to a ZonedDateTime fixes the issue.

[rjernst]

Thanks for the more detailed reproduction. I've tracked it down and have a fix: #53823.

[pgomulka]

@icalvete thank you for a great reproduction steps!
Can you please also confirm if you run the same version of ES in your cluster?
GET _cat/nodes?v&h=id,ip,port,version,master,name

I can confirm that this will fail in the same version cluster. @rjernst will fix this bug