Elasticsearch: ExecutableScriptTransform failed to execute [script] transform for [U3b6JOZnTUWFzm-...]

[jamiesmith]

Elasticsearch version (bin/elasticsearch --version):

Version: 6.4.0-SNAPSHOT, Build: default/tar/043eb2e/2018-08-02T08:50:48.565068Z, JVM: 10.0.2

Plugins installed: []
nothing extra

JVM version (java -version):
version in docker image:

openjdk version "10.0.2" 2018-07-17
OpenJDK Runtime Environment 18.3 (build 10.0.2+13)
OpenJDK 64-Bit Server VM 18.3 (build 10.0.2+13, mixed mode)

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

Linux 99d7986b9869 4.9.93-linuxkit-aufs #1 SMP Wed Jun 6 16:55:56 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux

Description of the problem including expected versus actual behavior:
watcher/script logs errors every few seconds o.e.x.w.t.s.ExecutableScriptTransform

Steps to reproduce:

curl -O https://snapshots.elastic.co/docker/kibana-6.4.0-SNAPSHOT.tar.gz
docker load -i kibana-6.4.0-SNAPSHOT.tar.gz

curl -O https://snapshots.elastic.co/docker/elasticsearch-6.4.0-SNAPSHOT.tar.gz
docker load -i elasticsearch-6.4.0-SNAPSHOT.tar.gz 

echo pause 10 for docker to settle

# for some reason compose isn't ready to run yet
sleep 10

# you need the attached compose file
docker-compose --file dc.txt up --detach

docker logs --follow localtesting_6.4.0_elasticsearch

After about a minute you will start seeing regular appearances of
[2018-08-02T15:00:36,813][ERROR][o.e.x.w.t.s.ExecutableScriptTransform] [0jRACy3] failed to execute [script] transform for [U3b6JOZnTUWFzm-LGTtFzA_elasticsearch_nodes_6af1eaac-1d2b-44d7-b9ca-5f41cbafdf1d-2018-08-02T15:00:36.701Z]
org.elasticsearch.script.ScriptException: runtime error (...)

(docker-compose file: dc.txt )

Provide logs (if relevant):

[2018-08-02T15:00:36,813][ERROR][o.e.x.w.t.s.ExecutableScriptTransform] [0jRACy3] failed to execute [script] transform for [U3b6JOZnTUWFzm-LGTtFzA_elasticsearch_nodes_6af1eaac-1d2b-44d7-b9ca-5f41cbafdf1d-2018-08-02T15:00:36.701Z]
org.elasticsearch.script.ScriptException: runtime error
    at org.elasticsearch.painless.PainlessScript.convertToScriptException(PainlessScript.java:94) ~[?:?]
    at org.elasticsearch.painless.PainlessScript$Script.execute(void formatResults(StringBuilder message, String type, Map typeMap) {if (typeMap.empty == false) {message.append(' Node');if (typeMap.size() != 1) {message.append('s were');} else {message.append(' was');}message.append(' ').append(type).append(' [').appen ...:1988) ~[?:?]
    at org.elasticsearch.painless.ScriptImpl.run(ScriptImpl.java:105) ~[?:?]
    at org.elasticsearch.xpack.watcher.transform.script.ExecutableScriptTransform.doExecute(ExecutableScriptTransform.java:57) ~[x-pack-watcher-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
    at org.elasticsearch.xpack.watcher.transform.script.ExecutableScriptTransform.execute(ExecutableScriptTransform.java:41) [x-pack-watcher-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
    at org.elasticsearch.xpack.watcher.transform.script.ExecutableScriptTransform.execute(ExecutableScriptTransform.java:26) [x-pack-watcher-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
    at org.elasticsearch.xpack.watcher.execution.ExecutionService.executeInner(ExecutionService.java:453) [x-pack-watcher-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
    at org.elasticsearch.xpack.watcher.execution.ExecutionService.execute(ExecutionService.java:295) [x-pack-watcher-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
    at org.elasticsearch.xpack.watcher.execution.ExecutionService.lambda$executeAsync$6(ExecutionService.java:398) [x-pack-watcher-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
    at org.elasticsearch.xpack.watcher.execution.ExecutionService$WatchExecutionTask.run(ExecutionService.java:553) [x-pack-watcher-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
    at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingRunnable.run(ThreadContext.java:624) [elasticsearch-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1135) [?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
    at java.lang.Thread.run(Thread.java:844) [?:?]
Caused by: java.lang.NullPointerException
    at org.elasticsearch.painless.DefBootstrap$PIC.fallback(DefBootstrap.java:203) ~[?:?]
    at org.elasticsearch.painless.PainlessScript$Script.execute(void formatResults(StringBuilder message, String type, Map typeMap) {if (typeMap.empty == false) {message.append(' Node');if (typeMap.size() != 1) {message.append('s were');} else {message.append(' was');}message.append(' ').append(type).append(' [').appen ...:525) ~[?:?]
    ... 12 more

[elasticmachine]

Pinging @elastic/es-core-infra

[jdconrad]

@jamiesmith Forgive me if I missed it, but I don't see the full script posted anywhere, just the snippet. Do you have the full script easily available? I'd like to use it to try to reproduce this issue locally. Thanks in advance.

[jamiesmith]

the steps are all that you need to do:

curl -O https://snapshots.elastic.co/docker/kibana-6.4.0-SNAPSHOT.tar.gz
docker load -i kibana-6.4.0-SNAPSHOT.tar.gz

curl -O https://snapshots.elastic.co/docker/elasticsearch-6.4.0-SNAPSHOT.tar.gz
docker load -i elasticsearch-6.4.0-SNAPSHOT.tar.gz 

echo pause 10 for docker to settle

# for some reason compose isn't ready to run yet
sleep 10

# you need the attached compose file
docker-compose --file dc.txt up --detach

docker logs --follow localtesting_6.4.0_elasticsearch

the dc.txt file is attached to the first issue

You don't have to _do_ anything - the errors appear in the logs about a minute after the node starts

[spinscale]

@jdconrad the script is part of a watch that monitoring installs when x-pack is enabled. See here

[jdconrad]

@jamiesmith @spinscale Thanks for the info. I'll take a look at that script and see if I can get it to repro locally.

[jdconrad]

@spinscale @jamiesmith This is a standard NullPointerException given as part of a poor error message (note error message improvement is on the painless roadmap). A method is being called against a def type that is null. After reviewing the script there are several places this could occur.

Calls against def types include the following:
latestNodes.entrySet()
previousNodes.entrySet()

It's possible I'm missing other calls against def that could be null but those two stand out.

@spinscale I don't know a huge amount about the data being accessed here, is it possible the source for latestNodes or previousNodes is null and not an empty Map? Should these be checked for in this script?

[jdconrad]

The formatted Painless script for easier viewing:

void formatResults(StringBuilder message, String type, Map typeMap) {
    if (typeMap.empty == false) {
        message.append(' Node');

        if (typeMap.size() != 1) {
            message.append('s were');
        } else {
            message.append(' was');
        }

        message.append(' ').append(type).append(' [').append(typeMap.size()).append(']: ').append(typeMap.values().
                stream().collect(Collectors.joining(', ', '[', ']'))).append('.');
    }
}

ctx.vars.email_recipient = (ctx.payload.kibana_settings.hits.total > 0) ?
        ctx.payload.kibana_settings.hits.hits[0]._source.kibana_settings.xpack.default_admin_email : null;

def clusterState = ctx.payload.check.hits.hits[0]._source.cluster_state;
def persistentUuidToName = [:];
def latestNodes = clusterState.nodes;
def ephemeralUuidToPersistentUuid = [:];
def payload = [
        'timestamp': ctx.execution_time,
        'updated_timestamp': ctx.execution_time,
        'resolved_timestamp': ctx.execution_time,
        'metadata': ctx.metadata.xpack,
        'prefix': 'Elasticsearch cluster nodes have changed!',
        'nodes': [
                'hash': clusterState.nodes_hash,
                'added': persistentUuidToName,
                'removed': [:],
                'restarted': [:]
        ]
];

for (def latestNode : latestNodes.entrySet()) {
    persistentUuidToName[latestNode.key] = latestNode.value.name;
    ephemeralUuidToPersistentUuid[latestNode.value.ephemeral_id] = latestNode.key;
}

def previousNodes = ctx.payload.check.hits.hits[1]._source.cluster_state.nodes;
def previousPersistentUuidToName = [:];
for (def previousNode : previousNodes.entrySet()) {
    if (persistentUuidToName.containsKey(previousNode.key) == false) {
        payload.nodes.removed[previousNode.key] = previousNode.value.name;
    } else {
        if (ephemeralUuidToPersistentUuid.containsKey(previousNode.value.ephemeral_id) == false) {
            payload.nodes.restarted[previousNode.key] = persistentUuidToName[previousNode.key];
        }

        persistentUuidToName.remove(previousNode.key);
    }
}

StringBuilder message = new StringBuilder();
formatResults(message, 'removed', payload.nodes.removed);
formatResults(message, 'added', payload.nodes.added);
formatResults(message, 'restarted', payload.nodes.restarted);
payload.message = message.toString().trim();

return payload;

[jdconrad]

@jasontedor figured out the cause of the NPE is ctx.payload.kibana_settings.hits.hits[0]._source.kibana_settings.xpack can be null. He proposed the following fix:

(ctx.payload.kibana_settings.hits.total > 0) ? ctx.payload.kibana_settings.hits.hits[0]._source.kibana_settings.xpack.default_admin_email : null

to

(ctx.payload.kibana_settings.hits.total > 0 && ctx.payload.kibana_settings.hits.hits[0]._source.kibana_settings.xpack != null) ? ctx.payload.kibana_settings.hits.hits[0]._source.kibana_settings.xpack.default_admin_email : null

This affects more than just this script, so all of them need to be updated.