search

elastic / elasticsearch

Free and Open Source, Distributed, RESTful Search Engine
https://www.elastic.co/products/elasticsearch
Other
1.2k stars 24.84k forks source link

[ci] SmokeTestWatcherTestSuiteIT.testMonitorClusterHealth #32299

Closed andyb-elastic closed 4 years ago

andyb-elastic commented 6 years ago

Doesn't reproduce, looks like the test cluster had a problem but there's nothing too interesting in the logs. This test has failed a handful of times in the last three months but for different resaons. Not sure there's anything to do here

https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+6.x+multijob-unix-compatibility/os=centos/1199/console

CI logs build-1199-watcher.txt

Integ cluster logs run.log

REPRODUCE WITH: ./gradlew :x-pack:qa:smoke-test-watcher:integTestRunner \
  -Dtests.seed=D4D1EB8646558B01 \
  -Dtests.class=org.elasticsearch.smoketest.SmokeTestWatcherTestSuiteIT \
  -Dtests.method="testMonitorClusterHealth" \
  -Dtests.security.manager=true \
  -Dtests.locale=ar-LB \
  -Dtests.timezone=America/Cuiaba
elasticmachine commented 6 years ago

Pinging @elastic/es-core-infra

andyb-elastic commented 6 years ago

Actually this does look odd from the integ cluster logs, though it happens after the request failing that fails the test

[2018-07-23T22:10:15,863][ERROR][o.e.s.m.MustacheScriptEngine] Error running com.github.mustachejava.codes.DefaultMustache@56a43cff
com.github.mustachejava.MustacheException: Failed to get value for ctx @[query-template:1]
        at com.github.mustachejava.codes.ValueCode.execute(ValueCode.java:74) ~[compiler-0.9.3.jar:?]
        at com.github.mustachejava.codes.DefaultMustache.run(DefaultMustache.java:34) ~[compiler-0.9.3.jar:?]
        at com.github.mustachejava.codes.DefaultCode.execute(DefaultCode.java:162) ~[compiler-0.9.3.jar:?]
        at com.github.mustachejava.codes.DefaultMustache.execute(DefaultMustache.java:55) ~[compiler-0.9.3.jar:?]
        at com.github.mustachejava.Mustache.execute(Mustache.java:38) ~[compiler-0.9.3.jar:?]
        at org.elasticsearch.script.mustache.MustacheScriptEngine$MustacheExecutableScript.lambda$execute$0(MustacheScriptEngine.java:111) ~[lang-mustache-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
        at java.security.AccessController.doPrivileged(Native Method) ~[?:?]
        at org.elasticsearch.script.mustache.MustacheScriptEngine$MustacheExecutableScript.execute(MustacheScriptEngine.java:110) [lang-mustache-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
        at org.elasticsearch.xpack.watcher.common.text.TextTemplateEngine.render(TextTemplateEngine.java:57) [x-pack-watcher-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
        at org.elasticsearch.xpack.watcher.actions.logging.ExecutableLoggingAction.execute(ExecutableLoggingAction.java:46) [x-pack-watcher-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
        at org.elasticsearch.xpack.core.watcher.actions.ActionWrapper.execute(ActionWrapper.java:144) [x-pack-core-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT] 
        at org.elasticsearch.xpack.watcher.execution.ExecutionService.executeInner(ExecutionService.java:464) [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.transport.actions.execute.TransportExecuteWatchAction$1.doRun(TransportExecuteWatchAction.java:154) [x-pack-watcher-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
        at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37) [elasticsearch-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:514) [?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
        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.IllegalArgumentException: Iterable object is self-referencing itself
        at org.elasticsearch.common.util.CollectionUtils.ensureNoSelfReferences(CollectionUtils.java:253) ~[elasticsearch-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
        at org.elasticsearch.common.util.CollectionUtils.ensureNoSelfReferences(CollectionUtils.java:256) ~[elasticsearch-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
        at org.elasticsearch.common.util.CollectionUtils.ensureNoSelfReferences(CollectionUtils.java:256) ~[elasticsearch-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
        at org.elasticsearch.common.util.CollectionUtils.ensureNoSelfReferences(CollectionUtils.java:256) ~[elasticsearch-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
        at org.elasticsearch.common.util.CollectionUtils.ensureNoSelfReferences(CollectionUtils.java:231) ~[elasticsearch-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
        at org.elasticsearch.script.mustache.CustomReflectionObjectHandler.stringify(CustomReflectionObjectHandler.java:160) ~[?:?]
        at com.github.mustachejava.codes.ValueCode.execute(ValueCode.java:69) ~[?:?]
        ... 20 more
jasontedor commented 6 years ago

Good catch @andyb-elastic.

dnhatn commented 6 years ago

Another instance: https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+intake/2645/consoleText

tvernum commented 5 years ago

I have enabled x-pack/qa/smoke-test-watcher again. I have covered the issues that I know about, but there's a comment above

This test has failed a handful of times in the last three months but for different resaons.

I don't have logs for all those, so it's possible that some still exist. Please re-mute this test if it turns out to still be flaky.

benwtrent commented 5 years ago

Another failure: https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+intake/2183/console

./gradlew :x-pack:qa:smoke-test-watcher:integTestRunner -Dtests.seed=921232DB4961CB4E -Dtests.class=org.elasticsearch.smoketest.SmokeTestWatcherTestSuiteIT -Dtests.method="testMonitorClusterHealth" -Dtests.security.manager=true -Dtests.locale=en-NZ -Dtests.timezone=Europe/Warsaw -Dcompiler.java=11 -Druntime.java=8
12:06:36 FAILURE 2.58s | SmokeTestWatcherTestSuiteIT.testMonitorClusterHealth <<< FAILURES!
12:06:36    > Throwable #1: java.lang.AssertionError: Watch count (from _watcher/stats)
12:06:36    > Expected: is <0>
12:06:36    >      but: was <1>
12:06:36    >   at __randomizedtesting.SeedInfo.seed([921232DB4961CB4E:61CAABBBBA00A4C4]:0)
12:06:36    >   at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
12:06:36    >   at org.elasticsearch.smoketest.SmokeTestWatcherTestSuiteIT.assertWatchCount(SmokeTestWatcherTestSuiteIT.java:230)
12:06:36    >   at org.elasticsearch.smoketest.SmokeTestWatcherTestSuiteIT.testMonitorClusterHealth(SmokeTestWatcherTestSuiteIT.java:162)
12:06:36    >   at java.lang.Thread.run(Thread.java:748)
12:06:36 Completed [3/3] in 2.61s, 1 test, 1 failure <<< FAILURES!
tvernum commented 5 years ago

Thanks, I'll look today and re-mute if needed.

tvernum commented 5 years ago

By piecing together the output from the test with the cluster log, I have a theory about what's happening here:

#TEST# [2019-02-21T19:06:35,018][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] Found [0] hits in watcher history

#NODE# [2019-02-21T18:06:35,070][DEBUG][o.e.x.w.t.s.e.TickerScheduleTriggerEngine] [node-0] triggered job [cluster_health_watch] at [2019-02-21T18:06:35.070Z] (scheduled time was [2019-02-21T18:06:34.919Z])
#NODE# [2019-02-21T18:06:35,081][INFO ][o.e.c.m.MetaDataCreateIndexService] [node-0] [.triggered_watches] creating index, cause [auto(bulk api)], templates [.triggered_watches], shards [1]/[1], mappings [doc]
#NODE# [2019-02-21T18:06:35,083][INFO ][o.e.c.r.a.AllocationService] [node-0] updating number_of_replicas to [0] for indices [.triggered_watches]
#NODE# [2019-02-21T18:06:35,155][INFO ][o.e.c.r.a.AllocationService] [node-0] Cluster health status changed from [YELLOW] to [GREEN] (reason: [shards started [[.triggered_watches][0]] ...]).
#NODE# [2019-02-21T18:06:35,184][DEBUG][o.e.x.w.e.ExecutionService] [node-0] executing watch [cluster_health_watch]
#NODE# [2019-02-21T18:06:35,212][INFO ][o.e.x.w.a.l.ExecutableLoggingAction] [node-0] executed
#NODE# [2019-02-21T18:06:35,215][DEBUG][o.e.x.w.WatcherIndexingListener] [node-0] adding watch [cluster_health_watch] to trigger service
#NODE# [2019-02-21T18:06:35,231][INFO ][o.e.c.m.MetaDataCreateIndexService] [node-0] [.watcher-history-9-2019.02.21] creating index, cause [auto(bulk api)], templates [.watch-history-9], shards [1]/[0], mappings [doc]
#NODE# [2019-02-21T18:06:35,299][INFO ][o.e.c.r.a.AllocationService] [node-0] Cluster health status changed from [YELLOW] to [GREEN] (reason: [shards started [[.watcher-history-9-2019.02.21][0]] ...])
#NODE# [2019-02-21T18:06:35,327][INFO ][o.e.c.m.MetaDataMappingService] [node-0] [.watcher-history-9-2019.02.21/KRXX-Mz_QzeQXiarK-39yw] update_mapping [doc]
#NODE# [2019-02-21T18:06:35,373][DEBUG][o.e.x.w.e.ExecutionService] [node-0] finished [cluster_health_watch]/[cluster_health_watch_53e3c983-2cc4-48e8-85e2-e27e15af89b9-2019-02-21T18:06:35.072183Z]

#TEST# [2019-02-21T19:06:36,043][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] Refreshing watcher history
#TEST# [2019-02-21T19:06:36,079][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] Searching watcher history

#NODE# [2019-02-21T18:06:36,078][DEBUG][o.e.x.w.t.s.e.TickerScheduleTriggerEngine] [node-0] triggered job [cluster_health_watch] at [2019-02-21T18:06:36.077Z] (scheduled time was [2019-02-21T18:06:35.919Z])
#NODE# [2019-02-21T18:06:36,089][DEBUG][o.e.x.w.e.ExecutionService] [node-0] executing watch [cluster_health_watch]

#TEST# [2019-02-21T19:06:36,093][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] Found [1] hits in watcher history
#TEST# [2019-02-21T19:06:36,093][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] Watch hit 0 has id [cluster_health_watch] (expecting [cluster_health_watch])

#NODE# [2019-02-21T18:06:36,098][DEBUG][o.e.x.w.WatcherIndexingListener] [node-0] adding watch [cluster_health_watch] to trigger service
#NODE# [2019-02-21T18:06:36,103][DEBUG][o.e.x.w.e.ExecutionService] [node-0] failed to execute watch [cluster_health_watch]
org.elasticsearch.index.engine.VersionConflictEngineException: [doc][cluster_health_watch]: version conflict, required seqNo [1], primary term [1]. current document has seqNo [2] and primary term [1]

#TEST# [2019-02-21T19:06:36,306][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] after test
#TEST  Watch count (from _watcher/stats) Expected: is <0> but: was <1>

It seems there was a concurrency issue between deleting the watch (somewhere between 19:06:36,093 and 19:06:36,306 in the test) and an executing of the test being written to the .watches index (around 18:06:36,098 on the node).

The watcher stats are driven from the TriggerService, and the WatcherIndexingListener updates the TriggerService as part of the preIndex method.

So delete watch removes the watch from the TriggerService which removes it from the stats count, but then the watch finishes executing which tries to update the .watches index, and that causes it to be added back to the TriggerService. The indexing to the watches index fails because of a version conflict (the delete), and the postIndex listener is supposed to detect that and clean up the TriggerService stats. And it might do, except the test has already failed by then, so the cluster shuts down.

I think an assertBusy on the assertWatchCount will do the trick, but it's a bit ugly.

I don't have time to fix it today, but will try to get a PR up next week.

tlrx commented 5 years ago

Failed again today: https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+periodic/800

It does not reproduce with:

./gradlew :x-pack:qa:smoke-test-watcher:integTestRunner -Dtests.seed=37D3466CC78964DE -Dtests.class=org.elasticsearch.smoketest.SmokeTestWatcherTestSuiteIT -Dtests.method="testMonitorClusterHealth" -Dtests.security.manager=true -Dtests.locale=ro -Dtests.timezone=PST -Dcompiler.java=11 -Druntime.java=8
04:35:05 1> [2019-02-26T20:35:00,582][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] before test 04:35:05 1> [2019-02-26T20:35:00,779][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] initializing REST clients against [http://[::1]:39892] 04:35:05 1> [2019-02-26T20:35:01,980][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] Successfully indexed watch with id [cluster_health_watch] 04:35:05 1> [2019-02-26T20:35:01,986][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] Watch count is [1] 04:35:05 1> [2019-02-26T20:35:01,987][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] Refreshing watcher history 04:35:05 1> [2019-02-26T20:35:01,992][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] Searching watcher history 04:35:05 1> [2019-02-26T20:35:02,006][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] Found [0] hits in watcher history 04:35:05 1> [2019-02-26T20:35:02,011][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] Refreshing watcher history 04:35:05 1> [2019-02-26T20:35:02,015][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] Searching watcher history 04:35:05 1> [2019-02-26T20:35:02,020][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] Found [0] hits in watcher history 04:35:05 1> [2019-02-26T20:35:02,023][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] Refreshing watcher history 04:35:05 1> [2019-02-26T20:35:02,026][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] Searching watcher history 04:35:05 1> [2019-02-26T20:35:02,032][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] Found [0] hits in watcher history 04:35:05 1> [2019-02-26T20:35:02,036][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] Refreshing watcher history 04:35:05 1> [2019-02-26T20:35:02,040][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] Searching watcher history 04:35:05 1> [2019-02-26T20:35:02,045][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] Found [0] hits in watcher history 04:35:05 1> [2019-02-26T20:35:02,053][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] Refreshing watcher history 04:35:05 1> [2019-02-26T20:35:02,057][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] Searching watcher history 04:35:05 1> [2019-02-26T20:35:02,062][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] Found [0] hits in watcher history 04:35:05 1> [2019-02-26T20:35:02,079][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] Refreshing watcher history 04:35:05 1> [2019-02-26T20:35:02,084][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] Searching watcher history 04:35:05 1> [2019-02-26T20:35:02,089][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] Found [0] hits in watcher history 04:35:05 1> [2019-02-26T20:35:02,122][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] Refreshing watcher history 04:35:05 1> [2019-02-26T20:35:02,127][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] Searching watcher history 04:35:05 1> [2019-02-26T20:35:02,132][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] Found [0] hits in watcher history 04:35:05 1> [2019-02-26T20:35:02,197][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] Refreshing watcher history 04:35:05 1> [2019-02-26T20:35:02,202][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] Searching watcher history 04:35:05 1> [2019-02-26T20:35:02,207][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] Found [0] hits in watcher history 04:35:05 1> [2019-02-26T20:35:02,336][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] Refreshing watcher history 04:35:05 1> [2019-02-26T20:35:02,340][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] Searching watcher history 04:35:05 1> [2019-02-26T20:35:02,345][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] Found [0] hits in watcher history 04:35:05 1> [2019-02-26T20:35:02,601][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] Refreshing watcher history 04:35:05 1> [2019-02-26T20:35:02,607][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] Searching watcher history 04:35:05 1> [2019-02-26T20:35:02,611][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] Found [0] hits in watcher history 04:35:05 1> [2019-02-26T20:35:03,124][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] Refreshing watcher history 04:35:05 1> [2019-02-26T20:35:03,130][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] Searching watcher history 04:35:05 1> [2019-02-26T20:35:03,136][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] Found [0] hits in watcher history 04:35:05 1> [2019-02-26T20:35:04,161][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] Refreshing watcher history 04:35:05 1> [2019-02-26T20:35:04,225][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] Searching watcher history 04:35:05 1> [2019-02-26T20:35:04,282][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] Found [1] hits in watcher history 04:35:05 1> [2019-02-26T20:35:04,282][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] Watch hit 0 has id [cluster_health_watch] (expecting [cluster_health_watch]) 04:35:05 1> [2019-02-26T20:35:04,644][INFO ][o.e.s.SmokeTestWatcherTestSuiteIT] [testMonitorClusterHealth] after test 04:35:05 FAILURE 4.11s | SmokeTestWatcherTestSuiteIT.testMonitorClusterHealth <<< FAILURES! 04:35:05 > Throwable #1: java.lang.AssertionError: Watch count (from _watcher/stats) 04:35:05 > Expected: is <0> 04:35:05 > but: was <1> 04:35:05 > at __randomizedtesting.SeedInfo.seed([37D3466CC78964DE:C40BDF0C34E80B54]:0) 04:35:05 > at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20) 04:35:05 > at org.elasticsearch.smoketest.SmokeTestWatcherTestSuiteIT.assertWatchCount(SmokeTestWatcherTestSuiteIT.java:230) 04:35:05 > at org.elasticsearch.smoketest.SmokeTestWatcherTestSuiteIT.testMonitorClusterHealth(SmokeTestWatcherTestSuiteIT.java:162) 04:35:05 > at java.lang.Thread.run(Thread.java:748) 04:35:05 Completed [1/3] in 5.52s, 1 test, 1 failure <<< FAILURES! 04:35:05 04:35:13 Suite: org.elasticsearch.smoketest.WatcherRestIT 04:35:13 Completed [2/3] in 7.98s, 19 tests 04:35:13 04:35:13 Suite: org.elasticsearch.smoketest.WatcherTemplateTests 04:35:13 Completed [3/3] in 0.21s, 3 tests 04:35:13 04:35:13 [ant:junit4] JVM J0: stderr was not empty, see: /var/lib/jenkins/workspace/elastic+elasticsearch+master+periodic/x-pack/qa/smoke-test-watcher/build/testrun/integTestRunner/temp/junit4-J0-20190227_043458_7637981882383782499459.syserr 04:35:13 04:35:13 > Task :x-pack:qa:smoke-test-watcher:integTestRunner FAILED 04:35:13 Tests with failures: 04:35:13 - org.elasticsearch.smoketest.SmokeTestWatcherTestSuiteIT.testMonitorClusterHealth 04:35:13 04:35:13 Slow Tests Summary: 04:35:13 7.98s | org.elasticsearch.smoketest.WatcherRestIT 04:35:13 5.52s | org.elasticsearch.smoketest.SmokeTestWatcherTestSuiteIT 04:35:13 0.21s | org.elasticsearch.smoketest.WatcherTemplateTests 04:35:13 04:35:13 [ant:junit4] JVM J0: 0.27 .. 14.82 = 14.55s 04:35:13 [ant:junit4] Execution time total: 14 seconds 04:35:13 [ant:junit4] Tests summary: 3 suites, 23 tests, 1 failure 04:35:13 04:35:13 Cluster x-pack_qa_smoke-test-watcher_integTestCluster - node 0 log excerpt: 04:35:13 (full log at /var/lib/jenkins/workspace/elastic+elasticsearch+master+periodic/x-pack/qa/smoke-test-watcher/build/cluster/integTestCluster node0/elasticsearch-8.0.0-SNAPSHOT/logs/x-pack_qa_smoke-test-watcher_integTestCluster.log) 04:35:13 ----------------------------------------- 04:35:13 [2019-02-27T04:34:51,913][INFO ][o.e.e.NodeEnvironment ] [node-0] using [1] data paths, mounts [[/ (rootfs)]], net usable_space [232gb], net total_space [299.9gb], types [rootfs] 04:35:13 [2019-02-27T04:34:51,917][INFO ][o.e.e.NodeEnvironment ] [node-0] heap size [494.9mb], compressed ordinary object pointers [true] 04:35:13 [2019-02-27T04:34:51,920][INFO ][o.e.n.Node ] [node-0] node name [node-0], node ID [u8lpcbgsSQ2WlEiI1SYlSA] 04:35:13 [2019-02-27T04:34:51,921][INFO ][o.e.n.Node ] [node-0] version[8.0.0-SNAPSHOT], pid[275430], build[default/tar/eae83fd/2019-02-27T01:28:14.922909Z], OS[Linux/3.10.0-957.5.1.el7.x86_64/amd64], JVM[Oracle Corporation/Java HotSpot(TM) 64-Bit Server VM/11.0.2/11.0.2+9-LTS] 04:35:13 [2019-02-27T04:34:51,921][INFO ][o.e.n.Node ] [node-0] JVM arguments [-Xms1g, -Xmx1g, -XX:+UseConcMarkSweepGC, -XX:CMSInitiatingOccupancyFraction=75, -XX:+UseCMSInitiatingOccupancyOnly, -Des.networkaddress.cache.ttl=60, -Des.networkaddress.cache.negative.ttl=10, -XX:+AlwaysPreTouch, -Xss1m, -Djava.awt.headless=true, -Dfile.encoding=UTF-8, -Djna.nosys=true, -XX:-OmitStackTraceInFastThrow, -Dio.netty.noUnsafe=true, -Dio.netty.noKeySetOptimization=true, -Dio.netty.recycler.maxCapacityPerThread=0, -Dlog4j.shutdownHookEnabled=false, -Dlog4j2.disable.jmx=true, -Djava.io.tmpdir=/tmp/elasticsearch-6033938558246586518, -XX:+HeapDumpOnOutOfMemoryError, -XX:HeapDumpPath=data, -XX:ErrorFile=logs/hs_err_pid%p.log, -Xlog:gc*,gc+age=trace,safepoint:file=logs/gc.log:utctime,pid,tags:filecount=32,filesize=64m, -Djava.locale.providers=COMPAT, -XX:UseAVX=2, -Dio.netty.allocator.type=unpooled, -Xms512m, -Xmx512m, -ea, -esa, -Des.path.home=/var/lib/jenkins/workspace/elastic+elasticsearch+master+periodic/x-pack/qa/smoke-test-watcher/build/cluster/integTestCluster node0/elasticsearch-8.0.0-SNAPSHOT, -Des.path.conf=/var/lib/jenkins/workspace/elastic+elasticsearch+master+periodic/x-pack/qa/smoke-test-watcher/build/cluster/integTestCluster node0/elasticsearch-8.0.0-SNAPSHOT/config, -Des.distribution.flavor=default, -Des.distribution.type=tar] 04:35:13 [2019-02-27T04:34:51,922][WARN ][o.e.n.Node ] [node-0] version [8.0.0-SNAPSHOT] is a pre-release version of Elasticsearch and is not suitable for production 04:35:13 [2019-02-27T04:34:53,631][INFO ][o.e.p.PluginsService ] [node-0] loaded module [aggs-matrix-stats] 04:35:13 [2019-02-27T04:34:53,632][INFO ][o.e.p.PluginsService ] [node-0] loaded module [analysis-common] 04:35:13 [2019-02-27T04:34:53,632][INFO ][o.e.p.PluginsService ] [node-0] loaded module [data-frame] 04:35:13 [2019-02-27T04:34:53,633][INFO ][o.e.p.PluginsService ] [node-0] loaded module [ingest-common] 04:35:13 [2019-02-27T04:34:53,634][INFO ][o.e.p.PluginsService ] [node-0] loaded module [ingest-geoip] 04:35:13 [2019-02-27T04:34:53,634][INFO ][o.e.p.PluginsService ] [node-0] loaded module [ingest-user-agent] 04:35:13 [2019-02-27T04:34:53,634][INFO ][o.e.p.PluginsService ] [node-0] loaded module [lang-expression] 04:35:13 [2019-02-27T04:34:53,634][INFO ][o.e.p.PluginsService ] [node-0] loaded module [lang-mustache] 04:35:13 [2019-02-27T04:34:53,635][INFO ][o.e.p.PluginsService ] [node-0] loaded module [lang-painless] 04:35:13 [2019-02-27T04:34:53,635][INFO ][o.e.p.PluginsService ] [node-0] loaded module [mapper-extras] 04:35:13 [2019-02-27T04:34:53,635][INFO ][o.e.p.PluginsService ] [node-0] loaded module [parent-join] 04:35:13 [2019-02-27T04:34:53,636][INFO ][o.e.p.PluginsService ] [node-0] loaded module [percolator] 04:35:13 [2019-02-27T04:34:53,636][INFO ][o.e.p.PluginsService ] [node-0] loaded module [rank-eval] 04:35:13 [2019-02-27T04:34:53,636][INFO ][o.e.p.PluginsService ] [node-0] loaded module [reindex] 04:35:13 [2019-02-27T04:34:53,636][INFO ][o.e.p.PluginsService ] [node-0] loaded module [repository-url] 04:35:13 [2019-02-27T04:34:53,636][INFO ][o.e.p.PluginsService ] [node-0] loaded module [transport-netty4] 04:35:13 [2019-02-27T04:34:53,637][INFO ][o.e.p.PluginsService ] [node-0] loaded module [x-pack-ccr] 04:35:13 [2019-02-27T04:34:53,637][INFO ][o.e.p.PluginsService ] [node-0] loaded module [x-pack-core] 04:35:13 [2019-02-27T04:34:53,637][INFO ][o.e.p.PluginsService ] [node-0] loaded module [x-pack-deprecation] 04:35:13 [2019-02-27T04:34:53,637][INFO ][o.e.p.PluginsService ] [node-0] loaded module [x-pack-graph] 04:35:13 [2019-02-27T04:34:53,638][INFO ][o.e.p.PluginsService ] [node-0] loaded module [x-pack-ilm] 04:35:13 [2019-02-27T04:34:53,638][INFO ][o.e.p.PluginsService ] [node-0] loaded module [x-pack-logstash] 04:35:13 [2019-02-27T04:34:53,638][INFO ][o.e.p.PluginsService ] [node-0] loaded module [x-pack-ml] 04:35:13 [2019-02-27T04:34:53,638][INFO ][o.e.p.PluginsService ] [node-0] loaded module [x-pack-monitoring] 04:35:13 [2019-02-27T04:34:53,638][INFO ][o.e.p.PluginsService ] [node-0] loaded module [x-pack-rollup] 04:35:13 [2019-02-27T04:34:53,638][INFO ][o.e.p.PluginsService ] [node-0] loaded module [x-pack-security] 04:35:13 [2019-02-27T04:34:53,639][INFO ][o.e.p.PluginsService ] [node-0] loaded module [x-pack-sql] 04:35:13 [2019-02-27T04:34:53,639][INFO ][o.e.p.PluginsService ] [node-0] loaded module [x-pack-upgrade] 04:35:13 [2019-02-27T04:34:53,639][INFO ][o.e.p.PluginsService ] [node-0] loaded module [x-pack-watcher] 04:35:13 [2019-02-27T04:34:53,640][INFO ][o.e.p.PluginsService ] [node-0] no plugins loaded 04:35:13 [2019-02-27T04:34:57,336][INFO ][o.e.d.DiscoveryModule ] [node-0] using discovery type [zen] and seed hosts providers [settings, file] 04:35:13 [2019-02-27T04:34:58,019][INFO ][o.e.n.Node ] [node-0] initialized 04:35:13 [2019-02-27T04:34:58,020][INFO ][o.e.n.Node ] [node-0] starting ... 04:35:13 [2019-02-27T04:34:58,180][INFO ][o.e.t.TransportService ] [node-0] publish_address {127.0.0.1:37607}, bound_addresses {[::1]:40656}, {127.0.0.1:37607} 04:35:13 [2019-02-27T04:34:58,204][WARN ][o.e.d.FileBasedSeedHostsProvider] [node-0] expected, but did not find, a dynamic hosts list at [/var/lib/jenkins/workspace/elastic+elasticsearch+master+periodic/x-pack/qa/smoke-test-watcher/build/cluster/integTestCluster node0/elasticsearch-8.0.0-SNAPSHOT/config/unicast_hosts.txt] 04:35:13 [2019-02-27T04:34:58,206][INFO ][o.e.c.c.Coordinator ] [node-0] setting initial configuration to VotingConfiguration{u8lpcbgsSQ2WlEiI1SYlSA} 04:35:13 [2019-02-27T04:34:58,250][INFO ][o.e.h.AbstractHttpServerTransport] [node-0] publish_address {127.0.0.1:41472}, bound_addresses {[::1]:39892}, {127.0.0.1:41472} 04:35:13 [2019-02-27T04:34:58,252][INFO ][o.e.n.Node ] [node-0] started 04:35:13 [2019-02-27T04:34:58,282][INFO ][o.e.c.s.MasterService ] [node-0] elected-as-master ([1] nodes joined)[{node-0}{u8lpcbgsSQ2WlEiI1SYlSA}{Sturk2hjRDq3y4le33PmDw}{127.0.0.1}{127.0.0.1:37607}{xpack.installed=true, testattr=test} elect leader, _BECOME_MASTER_TASK_, _FINISH_ELECTION_], term: 1, version: 1, reason: master node changed {previous [], current [{node-0}{u8lpcbgsSQ2WlEiI1SYlSA}{Sturk2hjRDq3y4le33PmDw}{127.0.0.1}{127.0.0.1:37607}{xpack.installed=true, testattr=test}]} 04:35:13 [2019-02-27T04:34:58,326][INFO ][o.e.c.s.ClusterApplierService] [node-0] master node changed {previous [], current [{node-0}{u8lpcbgsSQ2WlEiI1SYlSA}{Sturk2hjRDq3y4le33PmDw}{127.0.0.1}{127.0.0.1:37607}{xpack.installed=true, testattr=test}]}, term: 1, version: 1, reason: Publication{term=1, version=1} 04:35:13 [2019-02-27T04:34:58,350][DEBUG][o.e.x.w.s.WatcherIndexTemplateRegistry] [node-0] adding index template [.triggered_watches], because it doesn't exist 04:35:13 [2019-02-27T04:34:58,351][DEBUG][o.e.x.w.s.WatcherIndexTemplateRegistry] [node-0] adding index template [.watch-history-9], because it doesn't exist 04:35:13 [2019-02-27T04:34:58,352][DEBUG][o.e.x.w.s.WatcherIndexTemplateRegistry] [node-0] adding index template [.watches], because it doesn't exist 04:35:13 [2019-02-27T04:34:58,386][INFO ][o.e.g.GatewayService ] [node-0] recovered [0] indices into cluster_state 04:35:13 [2019-02-27T04:34:58,412][WARN ][o.e.b.ElasticsearchUncaughtExceptionHandler] [node-0] uncaught exception in thread [elasticsearch[node-0][generic][T#2]] 04:35:13 java.lang.IllegalStateException: failed to find action [org.elasticsearch.xpack.core.indexlifecycle.action.PutLifecycleAction@d06806ea] to execute 04:35:13 at org.elasticsearch.client.node.NodeClient.transportAction(NodeClient.java:116) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] 04:35:13 at org.elasticsearch.client.node.NodeClient.executeLocally(NodeClient.java:83) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] 04:35:13 at org.elasticsearch.client.node.NodeClient.doExecute(NodeClient.java:72) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] 04:35:13 at org.elasticsearch.client.support.AbstractClient.execute(AbstractClient.java:393) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] 04:35:13 at org.elasticsearch.xpack.core.indexlifecycle.client.ILMClient.putLifecyclePolicy(ILMClient.java:42) ~[?:?] 04:35:13 at org.elasticsearch.xpack.watcher.support.WatcherIndexTemplateRegistry.lambda$putPolicy$3(WatcherIndexTemplateRegistry.java:188) ~[?:?] 04:35:13 at org.elasticsearch.xpack.core.ClientHelper.executeAsyncWithOrigin(ClientHelper.java:83) ~[?:?] 04:35:13 at org.elasticsearch.xpack.watcher.support.WatcherIndexTemplateRegistry.lambda$putPolicy$4(WatcherIndexTemplateRegistry.java:171) ~[?:?] 04:35:13 at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingRunnable.run(ThreadContext.java:681) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] 04:35:13 at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[?:?] 04:35:13 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[?:?] 04:35:13 at java.lang.Thread.run(Thread.java:834) [?:?] 04:35:13 ... SKIPPED 80 LINES ... 04:35:13 [2019-02-27T04:35:05,541][ERROR][o.e.x.w.Watcher ] [node-0] triggered watches could not be deleted [my_logging_watch_1c43fcc2-2093-4ac2-87a3-c6b10a255a0c-2019-02-27T04:35:05.510914Z], failure [[.triggered_watches] IndexNotFoundException[no such index [.triggered_watches]]] 04:35:13 ... SKIPPED 37 LINES ... 04:35:13 [2019-02-27T04:35:06,446][ERROR][o.e.x.w.Watcher ] [node-0] triggered watches could not be deleted [my_watch_600f1dff-9778-4072-8e4f-e2fb500f94f5-2019-02-27T04:35:06.444438Z], failure [[.triggered_watches] IndexNotFoundException[no such index [.triggered_watches]]] 04:35:13 ... SKIPPED 3 LINES ... 04:35:13 [2019-02-27T04:35:06,494][ERROR][o.e.x.w.Watcher ] [node-0] triggered watches could not be deleted [my_watch_4a3cd295-9ead-406e-b348-fdac02df7114-2019-02-27T04:35:06.489475Z], failure [[.triggered_watches] IndexNotFoundException[no such index [.triggered_watches]]] 04:35:13 ... SKIPPED 21 LINES ... 04:35:13 [2019-02-27T04:35:07,074][ERROR][o.e.x.w.Watcher ] [node-0] triggered watches could not be deleted [my_exe_watch_6f85dfff-9302-43a5-ae60-03fc2e6b05a7-2019-02-27T04:35:06.905692Z], failure [[.triggered_watches] IndexNotFoundException[no such index [.triggered_watches]]] 04:35:13 ... SKIPPED 19 LINES ... 04:35:13 [2019-02-27T04:35:07,467][ERROR][o.e.x.w.Watcher ] [node-0] triggered watches could not be deleted [my_watch_c9b1fe1b-017b-40aa-9272-e27d2c2d5608-2019-02-27T04:35:07.464404Z], failure [[.triggered_watches] IndexNotFoundException[no such index [.triggered_watches]]] 04:35:13 ... SKIPPED 3 LINES ... 04:35:13 [2019-02-27T04:35:07,505][ERROR][o.e.x.w.Watcher ] [node-0] triggered watches could not be deleted [my_watch_2e5f2266-275f-460a-9fbe-5a99b7a7233b-2019-02-27T04:35:07.50331Z], failure [[.triggered_watches] IndexNotFoundException[no such index [.triggered_watches]]] 04:35:13 ... SKIPPED 67 LINES ... 04:35:13 [2019-02-27T04:35:09,000][ERROR][o.e.x.w.Watcher ] [node-0] triggered watches could not be deleted [my_exe_watch_fa140609-254f-4814-b14f-bf0fcc0cab55-2019-02-27T04:35:08.846498Z], failure [[.triggered_watches] IndexNotFoundException[no such index [.triggered_watches]]] 04:35:13 ... SKIPPED 32 LINES ... 04:35:13 [2019-02-27T04:35:09,862][ERROR][o.e.x.w.Watcher ] [node-0] triggered watches could not be deleted [test_watch_3c32ac97-38fc-4513-87a6-6f21e726d44c-2019-02-27T04:35:09.591496Z], failure [[.triggered_watches] IndexNotFoundException[no such index [.triggered_watches]]] 04:35:13 ... SKIPPED 52 LINES ... 04:35:13 [2019-02-27T04:35:11,260][ERROR][o.e.x.w.Watcher ] [node-0] triggered watches could not be deleted [test_watch_d4af228d-7aaa-466f-bed4-674d65f14f64-2019-02-27T04:35:11.211714Z], failure [[.triggered_watches] IndexNotFoundException[no such index [.triggered_watches]]] 04:35:13 ... SKIPPED 57 LINES ... 04:35:13 [2019-02-27T04:35:12,356][ERROR][o.e.s.m.MustacheScriptEngine] [node-0] Error running com.github.mustachejava.codes.DefaultMustache@786363e1 04:35:13 com.github.mustachejava.MustacheException: Failed to get value for ctx @[query-template:1] 04:35:13 at com.github.mustachejava.codes.ValueCode.execute(ValueCode.java:74) ~[compiler-0.9.3.jar:?] 04:35:13 at com.github.mustachejava.codes.DefaultMustache.run(DefaultMustache.java:34) ~[compiler-0.9.3.jar:?] 04:35:13 at com.github.mustachejava.codes.DefaultCode.execute(DefaultCode.java:162) ~[compiler-0.9.3.jar:?] 04:35:13 at com.github.mustachejava.codes.DefaultMustache.execute(DefaultMustache.java:55) ~[compiler-0.9.3.jar:?] 04:35:13 at com.github.mustachejava.Mustache.execute(Mustache.java:38) ~[compiler-0.9.3.jar:?] 04:35:13 at org.elasticsearch.script.mustache.MustacheScriptEngine$MustacheExecutableScript.lambda$execute$0(MustacheScriptEngine.java:119) ~[lang-mustache-client-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] 04:35:13 at java.security.AccessController.doPrivileged(Native Method) ~[?:?] 04:35:13 at org.elasticsearch.script.mustache.MustacheScriptEngine$MustacheExecutableScript.execute(MustacheScriptEngine.java:118) [lang-mustache-client-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] 04:35:13 at org.elasticsearch.xpack.watcher.common.text.TextTemplateEngine.render(TextTemplateEngine.java:58) [x-pack-watcher-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] 04:35:13 at org.elasticsearch.xpack.watcher.actions.logging.ExecutableLoggingAction.execute(ExecutableLoggingAction.java:45) [x-pack-watcher-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] 04:35:13 at org.elasticsearch.xpack.core.watcher.actions.ActionWrapper.execute(ActionWrapper.java:144) [x-pack-core-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] 04:35:13 at org.elasticsearch.xpack.watcher.execution.ExecutionService.executeInner(ExecutionService.java:460) [x-pack-watcher-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] 04:35:13 at org.elasticsearch.xpack.watcher.execution.ExecutionService.execute(ExecutionService.java:299) [x-pack-watcher-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] 04:35:13 at org.elasticsearch.xpack.watcher.transport.actions.execute.TransportExecuteWatchAction$1.doRun(TransportExecuteWatchAction.java:149) [x-pack-watcher-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] 04:35:13 at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37) [elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] 04:35:13 at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?] 04:35:13 at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?] 04:35:13 at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingRunnable.run(ThreadContext.java:681) [elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] 04:35:13 at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?] 04:35:13 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?] 04:35:13 at java.lang.Thread.run(Thread.java:834) [?:?] 04:35:13 Caused by: java.lang.IllegalArgumentException: Iterable object is self-referencing itself (CustomReflectionObjectHandler stringify) 04:35:13 at org.elasticsearch.common.util.CollectionUtils.ensureNoSelfReferences(CollectionUtils.java:267) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] 04:35:13 at org.elasticsearch.common.util.CollectionUtils.ensureNoSelfReferences(CollectionUtils.java:270) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] 04:35:13 at org.elasticsearch.common.util.CollectionUtils.ensureNoSelfReferences(CollectionUtils.java:270) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] 04:35:13 at org.elasticsearch.common.util.CollectionUtils.ensureNoSelfReferences(CollectionUtils.java:270) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] 04:35:13 at org.elasticsearch.common.util.CollectionUtils.ensureNoSelfReferences(CollectionUtils.java:242) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] 04:35:13 at org.elasticsearch.script.mustache.CustomReflectionObjectHandler.stringify(CustomReflectionObjectHandler.java:160) ~[lang-mustache-client-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] 04:35:13 at com.github.mustachejava.codes.ValueCode.execute(ValueCode.java:69) ~[compiler-0.9.3.jar:?] 04:35:13 ... 20 more 04:35:13 [2019-02-27T04:35:12,358][ERROR][o.e.x.w.a.l.ExecutableLoggingAction] [node-0] failed to execute action [_inlined_/my-logging] 04:35:13 org.elasticsearch.script.GeneralScriptException: Error running com.github.mustachejava.codes.DefaultMustache@786363e1 04:35:13 at org.elasticsearch.script.mustache.MustacheScriptEngine$MustacheExecutableScript.execute(MustacheScriptEngine.java:124) ~[?:?] 04:35:13 at org.elasticsearch.xpack.watcher.common.text.TextTemplateEngine.render(TextTemplateEngine.java:58) ~[?:?] 04:35:13 at org.elasticsearch.xpack.watcher.actions.logging.ExecutableLoggingAction.execute(ExecutableLoggingAction.java:45) ~[?:?] 04:35:13 at org.elasticsearch.xpack.core.watcher.actions.ActionWrapper.execute(ActionWrapper.java:144) [x-pack-core-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] 04:35:13 at org.elasticsearch.xpack.watcher.execution.ExecutionService.executeInner(ExecutionService.java:460) [x-pack-watcher-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] 04:35:13 at org.elasticsearch.xpack.watcher.execution.ExecutionService.execute(ExecutionService.java:299) [x-pack-watcher-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] 04:35:13 at org.elasticsearch.xpack.watcher.transport.actions.execute.TransportExecuteWatchAction$1.doRun(TransportExecuteWatchAction.java:149) [x-pack-watcher-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] 04:35:13 at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37) [elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] 04:35:13 at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?] 04:35:13 at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?] 04:35:13 at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingRunnable.run(ThreadContext.java:681) [elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] 04:35:13 at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?] 04:35:13 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?] 04:35:13 at java.lang.Thread.run(Thread.java:834) [?:?] 04:35:13 Caused by: com.github.mustachejava.MustacheException: Failed to get value for ctx @[query-template:1] 04:35:13 at com.github.mustachejava.codes.ValueCode.execute(ValueCode.java:74) ~[?:?] 04:35:13 at com.github.mustachejava.codes.DefaultMustache.run(DefaultMustache.java:34) ~[?:?] 04:35:13 at com.github.mustachejava.codes.DefaultCode.execute(DefaultCode.java:162) ~[?:?] 04:35:13 at com.github.mustachejava.codes.DefaultMustache.execute(DefaultMustache.java:55) ~[?:?] 04:35:13 at com.github.mustachejava.Mustache.execute(Mustache.java:38) ~[?:?] 04:35:13 at org.elasticsearch.script.mustache.MustacheScriptEngine$MustacheExecutableScript.lambda$execute$0(MustacheScriptEngine.java:119) ~[?:?] 04:35:13 at java.security.AccessController.doPrivileged(Native Method) ~[?:?] 04:35:13 at org.elasticsearch.script.mustache.MustacheScriptEngine$MustacheExecutableScript.execute(MustacheScriptEngine.java:118) ~[?:?] 04:35:13 ... 13 more 04:35:13 Caused by: java.lang.IllegalArgumentException: Iterable object is self-referencing itself (CustomReflectionObjectHandler stringify) 04:35:13 at org.elasticsearch.common.util.CollectionUtils.ensureNoSelfReferences(CollectionUtils.java:267) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] 04:35:13 at org.elasticsearch.common.util.CollectionUtils.ensureNoSelfReferences(CollectionUtils.java:270) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] 04:35:13 at org.elasticsearch.common.util.CollectionUtils.ensureNoSelfReferences(CollectionUtils.java:270) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] 04:35:13 at org.elasticsearch.common.util.CollectionUtils.ensureNoSelfReferences(CollectionUtils.java:270) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] 04:35:13 at org.elasticsearch.common.util.CollectionUtils.ensureNoSelfReferences(CollectionUtils.java:242) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] 04:35:13 at org.elasticsearch.script.mustache.CustomReflectionObjectHandler.stringify(CustomReflectionObjectHandler.java:160) ~[?:?] 04:35:13 at com.github.mustachejava.codes.ValueCode.execute(ValueCode.java:69) ~[?:?] 04:35:13 at com.github.mustachejava.codes.DefaultMustache.run(DefaultMustache.java:34) ~[?:?] 04:35:13 at com.github.mustachejava.codes.DefaultCode.execute(DefaultCode.java:162) ~[?:?] 04:35:13 at com.github.mustachejava.codes.DefaultMustache.execute(DefaultMustache.java:55) ~[?:?] 04:35:13 at com.github.mustachejava.Mustache.execute(Mustache.java:38) ~[?:?] 04:35:13 at org.elasticsearch.script.mustache.MustacheScriptEngine$MustacheExecutableScript.lambda$execute$0(MustacheScriptEngine.java:119) ~[?:?] 04:35:13 at java.security.AccessController.doPrivileged(Native Method) ~[?:?] 04:35:13 at org.elasticsearch.script.mustache.MustacheScriptEngine$MustacheExecutableScript.execute(MustacheScriptEngine.java:118) ~[?:?] 04:35:13 ... 13 more 04:35:13 ========================================= 04:35:13 :x-pack:qa:smoke-test-watcher:integTestRunner (Thread[Execution worker for ':' Thread 7,5,main]) completed. Took 14.863 secs. 04:35:13 :x-pack:qa:smoke-test-watcher:integTestCluster#stop (Thread[Execution worker for ':' Thread 7,5,main]) started. 04:35:13 04:35:13 > Task :x-pack:qa:smoke-test-watcher:integTestCluster#stop 04:35:13 Task ':x-pack:qa:smoke-test-watcher:integTestCluster#stop' is not up-to-date because: 04:35:13 Task has not declared any outputs despite executing actions. 04:35:13 Custom actions are attached to task ':x-pack:qa:smoke-test-watcher:integTestCluster#stop'. 04:35:13 Shutting down external node with pid 275430 04:35:13 Starting process 'command 'kill''. Working directory: /var/lib/jenkins/workspace/elastic+elasticsearch+master+periodic/x-pack/qa/smoke-test-watcher Command: kill -9 275430 04:35:13 Successfully started process 'command 'kill'' 04:35:13 :x-pack:qa:smoke-test-watcher:integTestCluster#stop (Thread[Execution worker for ':' Thread 7,5,main]) completed. Took 0.006 secs. 04:35:13 04:35:13 04:35:13 FAILURE: Build failed with an exception. 04:35:13 Deprecated Gradle features were used in this build, making it incompatible with Gradle 6.0. 04:35:13 Use '--warning-mode all' to show the individual deprecation warnings. 04:35:13 See https://docs.gradle.org/5.2.1/userguide/command_line_interface.html#sec:command_line_warnings 04:35:13 04:35:13 4998 actionable tasks: 2646 executed, 2352 up-to-date 04:35:13 * What went wrong: 04:35:13 Execution failed for task ':x-pack:qa:smoke-test-watcher:integTestRunner'. 04:35:13 > There were test failures: 3 suites, 23 tests, 1 failure [seed: 37D3466CC78964DE] 04:35:13 04:35:13 * Try: 04:35:13 Run with --stacktrace option to get the stack trace. Run with --debug option to get more log output. Run with --scan to get full insights. 04:35:13 04:35:13 * Get more help at https://help.gradle.org 04:35:13 04:35:13 BUILD FAILED in 2h 58m 10s 04:35:13 04:35:13 Publishing build scan... 04:35:14 https://gradle.com/s/f2z2tmrm2icti 04:35:14 04:35:15 runbld>>> <<<<<<<<<<<< SCRIPT EXECUTION END <<<<<<<<<<<< 04:35:15 runbld>>> DURATION: 11384070ms 04:35:15 runbld>>> STDOUT: 24661127 bytes 04:35:15 runbld>>> STDERR: 115672 bytes 04:35:15 runbld>>> WRAPPED PROCESS: FAILURE (1) 04:35:15 runbld>>> Searching for build metadata in /var/lib/jenkins/workspace/elastic+elasticsearch+master+periodic 04:35:23 runbld>>> Storing build metadata: bwc_refspec_distribution:bwc:minor=a9e86bc941776083ca36525fdecd4b1944d1f199;bwc_refspec_distribution:bwc:staged=4f1a0cc4fd15acd67b47fe01ba4aea37a41dd547 04:35:23 runbld>>> Adding test report. 04:35:23 runbld>>> Searching for junit test output files with the pattern: TEST-.*\.xml$ in: /var/lib/jenkins/workspace/elastic+elasticsearch+master+periodic 04:35:30 runbld>>> Found 3790 test output files 04:36:05 runbld>>> Test output logs contained: Errors: 0 Failures: 1 Tests: 35311 Skipped: 652 04:36:05 runbld>>> Storing result 04:36:05 runbld>>> FAILURES: 1 04:36:06 runbld>>> Store result: updated {:total 2, :successful 2, :failed 0} 2 04:36:06 runbld>>> BUILD: https://c150076387b5421f9154dfbf536e5c60.us-west1.gcp.cloud.es.io:9243/build-1531848254847/t/20190227012527-DD895739 04:36:19 runbld>>> MAILING: build-elasticsearch@e***.co 04:36:21 runbld>>> Mail sent. Output: {:code 0, :error :SUCCESS, :message "messages sent"}

I muted the test again in 69fe79a85ea27ad6228ecde02d54cad83b462f6d

martijnvg commented 4 years ago

It just failed again with the above commit: https://gradle-enterprise.elastic.co/s/4665fyvjoklhy

I'm going to mute the test for now and look into the logs that have been produced.

polyfractal commented 4 years ago

Failure with NPE, but I think this might be from the test itself

https://gradle-enterprise.elastic.co/s/mjpliukhzhawm

./gradlew ':x-pack:qa:smoke-test-watcher:integTestRunner' --tests "org.elasticsearch.smoketest.SmokeTestWatcherTestSuiteIT.testMonitorClusterHealth" \
  -Dtests.seed=849FC7F5DD295954 \
  -Dtests.security.manager=true \
  -Dtests.locale=th-TH \
  -Dtests.timezone=Asia/Nicosia \
  -Dcompiler.java=13
java.lang.NullPointerException
        at __randomizedtesting.SeedInfo.seed([849FC7F5DD295954:77475E952E4836DE]:0)
        at org.elasticsearch.smoketest.SmokeTestWatcherTestSuiteIT.testMonitorClusterHealth(SmokeTestWatcherTestSuiteIT.java:159)
martijnvg commented 4 years ago

Thanks @polyfractal. This test failed a few times. I will mute it and investigate the logs.

martijnvg commented 4 years ago

The NPE is caused by the fact that history docs where returned with a state :not_executed_already_queued. This events docs have a result json object, which causes the code to retrieve hits.hits.0._source.result.condition.met to return null. The test then tries to cast this is a boolean, which results in a NPE. The history doc that does contain a result object is returned, but not as the first hit. I will fix this shortly.

martijnvg commented 4 years ago

This test has failed a few times over the weekend. I will mute this test and analyse the failures.

martijnvg commented 4 years ago

I think #51466 has fixed this issue. If this test fails again then a new issue should be opened and possible reference this issue if the failure looks similar.