[ci] SmokeTestWatcherTestSuiteIT.testMonitorClusterHealth #32299

andyb-elastic · 2018-07-23T20:53:29Z

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

The text was updated successfully, but these errors were encountered:

elasticmachine · 2018-07-23T20:53:30Z

Pinging @elastic/es-core-infra

andyb-elastic · 2018-07-23T20:54:21Z

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 · 2018-07-25T05:07:45Z

Good catch @andyb-elastic.

Tracked at elastic#32299

dnhatn · 2018-08-30T18:30:15Z

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

Tracked at #32299

tvernum · 2019-02-20T23:53:54Z

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 · 2019-02-21T20:23:45Z

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 · 2019-02-21T22:52:41Z

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

tvernum · 2019-02-22T07:47:29Z

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 · 2019-02-27T13:37:04Z

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 69fe79a

Tracked in #32299

Also adds `assertWatchCount(0)` snippet inside assertBusy(...) based on the findings in: elastic#32299 (comment) Relates to elastic#32299

Also adds `assertWatchCount(0)` snippet inside assertBusy(...) based on the findings in: #32299 (comment) Relates to #32299

martijnvg · 2020-01-16T16:33:53Z

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.

See #32299

I suspect that the watch doesn't get removed after a index operation failure. Based from the latest failure: elastic#32299 (comment) Watch gets added several time (due to updates to the watch): [2020-01-16T12:06:25,718][DEBUG][o.e.x.w.WatcherIndexingListener] [integTest-0] adding watch [cluster_health_watch] to trigger service ... [2020-01-16T12:06:27,112][DEBUG][o.e.x.w.e.ExecutionService] [integTest-0] executing watch [cluster_health_watch] ... [2020-01-16T12:06:27,159][DEBUG][o.e.x.w.WatcherIndexingListener] [integTest-0] adding watch [cluster_health_watch] to trigger service ... [2020-01-16T12:06:27,975][DEBUG][o.e.x.w.e.ExecutionService] [integTest-0] executing watch [cluster_health_watch] ... [2020-01-16T12:06:27,987][DEBUG][o.e.x.w.WatcherIndexingListener] [integTest-0] adding watch [cluster_health_watch] to trigger service Then the watch gets deleted (no proof of that in the log), but because of that the update to the watch fails: ``` [2020-01-16T12:06:28,009][DEBUG][o.e.x.w.e.ExecutionService] [integTest-0] failed to execute watch [cluster_health_watch] org.elasticsearch.index.engine.VersionConflictEngineException: [cluster_health_watch]: version conflict, required seqNo [1], primary term [1]. but no document was found at org.elasticsearch.index.engine.InternalEngine.planIndexingAsPrimary(InternalEngine.java:1037) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] at org.elasticsearch.index.engine.InternalEngine.indexingStrategyForOperation(InternalEngine.java:1007) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] at org.elasticsearch.index.engine.InternalEngine.index(InternalEngine.java:896) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] at org.elasticsearch.index.shard.IndexShard.index(IndexShard.java:803) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] at org.elasticsearch.index.shard.IndexShard.applyIndexOperation(IndexShard.java:775) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] at org.elasticsearch.index.shard.IndexShard.applyIndexOperationOnPrimary(IndexShard.java:740) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] at org.elasticsearch.action.bulk.TransportShardBulkAction.executeBulkItemRequest(TransportShardBulkAction.java:256) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] at org.elasticsearch.action.bulk.TransportShardBulkAction$2.doRun(TransportShardBulkAction.java:159) ~[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 org.elasticsearch.action.bulk.TransportShardBulkAction.performOnPrimary(TransportShardBulkAction.java:191) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] at org.elasticsearch.action.bulk.TransportShardBulkAction.shardOperationOnPrimary(TransportShardBulkAction.java:116) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] at org.elasticsearch.action.bulk.TransportShardBulkAction.shardOperationOnPrimary(TransportShardBulkAction.java:82) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] at org.elasticsearch.action.support.replication.TransportReplicationAction$PrimaryShardReference.perform(TransportReplicationAction.java:894) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0. 0-SNAPSHOT] at org.elasticsearch.action.support.replication.ReplicationOperation.execute(ReplicationOperation.java:109) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] at org.elasticsearch.action.support.replication.TransportReplicationAction$AsyncPrimaryAction.runWithPrimaryShardReference(TransportReplicationAction.java:373) ~[elasticsearch-8.0.0 -SNAPSHOT.jar:8.0.0-SNAPSHOT] at org.elasticsearch.action.support.replication.TransportReplicationAction$AsyncPrimaryAction.lambda$doRun$0(TransportReplicationAction.java:296) ~[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.index.shard.IndexShard.lambda$wrapPrimaryOperationPermitListener$24(IndexShard.java:2763) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] at org.elasticsearch.action.ActionListener$3.onResponse(ActionListener.java:113) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] at org.elasticsearch.index.shard.IndexShardOperationPermits.acquire(IndexShardOperationPermits.java:285) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] at org.elasticsearch.index.shard.IndexShardOperationPermits.acquire(IndexShardOperationPermits.java:237) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] at org.elasticsearch.index.shard.IndexShard.acquirePrimaryOperationPermit(IndexShard.java:2737) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] at org.elasticsearch.action.support.replication.TransportReplicationAction.acquirePrimaryOperationPermit(TransportReplicationAction.java:835) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] at org.elasticsearch.action.support.replication.TransportReplicationAction$AsyncPrimaryAction.doRun(TransportReplicationAction.java:292) ~[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 org.elasticsearch.action.support.replication.TransportReplicationAction.handlePrimaryRequest(TransportReplicationAction.java:255) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] at org.elasticsearch.transport.RequestHandlerRegistry.processMessageReceived(RequestHandlerRegistry.java:63) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] at org.elasticsearch.transport.TransportService$7.doRun(TransportService.java:692) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:688) ~[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:834) [?:?] ``` I think the additional logging will give more insight why the watch is not removed from the trigger service, which causes the watch count to be off. Relates to elastic#32299

Also adds `assertWatchCount(0)` snippet inside assertBusy(...) based on the findings in: elastic#32299 (comment) Relates to elastic#32299

See elastic#32299

I suspect that the watch doesn't get removed after an index operation failure. Based from the latest failure: #32299 (comment) Watch gets added several time (due to updates to the watch): [2020-01-16T12:06:25,718][DEBUG][o.e.x.w.WatcherIndexingListener] [integTest-0] adding watch [cluster_health_watch] to trigger service ... [2020-01-16T12:06:27,112][DEBUG][o.e.x.w.e.ExecutionService] [integTest-0] executing watch [cluster_health_watch] ... [2020-01-16T12:06:27,159][DEBUG][o.e.x.w.WatcherIndexingListener] [integTest-0] adding watch [cluster_health_watch] to trigger service ... [2020-01-16T12:06:27,975][DEBUG][o.e.x.w.e.ExecutionService] [integTest-0] executing watch [cluster_health_watch] ... [2020-01-16T12:06:27,987][DEBUG][o.e.x.w.WatcherIndexingListener] [integTest-0] adding watch [cluster_health_watch] to trigger service Then the watch gets deleted (no proof of that in the log), but because of that the update to the watch fails: ``` [2020-01-16T12:06:28,009][DEBUG][o.e.x.w.e.ExecutionService] [integTest-0] failed to execute watch [cluster_health_watch] org.elasticsearch.index.engine.VersionConflictEngineException: [cluster_health_watch]: version conflict, required seqNo [1], primary term [1]. but no document was found at org.elasticsearch.index.engine.InternalEngine.planIndexingAsPrimary(InternalEngine.java:1037) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] at org.elasticsearch.index.engine.InternalEngine.indexingStrategyForOperation(InternalEngine.java:1007) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] at org.elasticsearch.index.engine.InternalEngine.index(InternalEngine.java:896) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] at org.elasticsearch.index.shard.IndexShard.index(IndexShard.java:803) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] at org.elasticsearch.index.shard.IndexShard.applyIndexOperation(IndexShard.java:775) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] at org.elasticsearch.index.shard.IndexShard.applyIndexOperationOnPrimary(IndexShard.java:740) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] at org.elasticsearch.action.bulk.TransportShardBulkAction.executeBulkItemRequest(TransportShardBulkAction.java:256) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] at org.elasticsearch.action.bulk.TransportShardBulkAction$2.doRun(TransportShardBulkAction.java:159) ~[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 org.elasticsearch.action.bulk.TransportShardBulkAction.performOnPrimary(TransportShardBulkAction.java:191) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] at org.elasticsearch.action.bulk.TransportShardBulkAction.shardOperationOnPrimary(TransportShardBulkAction.java:116) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] at org.elasticsearch.action.bulk.TransportShardBulkAction.shardOperationOnPrimary(TransportShardBulkAction.java:82) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] at org.elasticsearch.action.support.replication.TransportReplicationAction$PrimaryShardReference.perform(TransportReplicationAction.java:894) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0. 0-SNAPSHOT] at org.elasticsearch.action.support.replication.ReplicationOperation.execute(ReplicationOperation.java:109) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] at org.elasticsearch.action.support.replication.TransportReplicationAction$AsyncPrimaryAction.runWithPrimaryShardReference(TransportReplicationAction.java:373) ~[elasticsearch-8.0.0 -SNAPSHOT.jar:8.0.0-SNAPSHOT] at org.elasticsearch.action.support.replication.TransportReplicationAction$AsyncPrimaryAction.lambda$doRun$0(TransportReplicationAction.java:296) ~[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.index.shard.IndexShard.lambda$wrapPrimaryOperationPermitListener$24(IndexShard.java:2763) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] at org.elasticsearch.action.ActionListener$3.onResponse(ActionListener.java:113) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] at org.elasticsearch.index.shard.IndexShardOperationPermits.acquire(IndexShardOperationPermits.java:285) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] at org.elasticsearch.index.shard.IndexShardOperationPermits.acquire(IndexShardOperationPermits.java:237) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] at org.elasticsearch.index.shard.IndexShard.acquirePrimaryOperationPermit(IndexShard.java:2737) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] at org.elasticsearch.action.support.replication.TransportReplicationAction.acquirePrimaryOperationPermit(TransportReplicationAction.java:835) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] at org.elasticsearch.action.support.replication.TransportReplicationAction$AsyncPrimaryAction.doRun(TransportReplicationAction.java:292) ~[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 org.elasticsearch.action.support.replication.TransportReplicationAction.handlePrimaryRequest(TransportReplicationAction.java:255) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] at org.elasticsearch.transport.RequestHandlerRegistry.processMessageReceived(RequestHandlerRegistry.java:63) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] at org.elasticsearch.transport.TransportService$7.doRun(TransportService.java:692) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT] at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:688) ~[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:834) [?:?] ``` I think the additional logging will give more insight why the watch is not removed from the trigger service, which causes the watch count to be off. Relates to #32299

polyfractal · 2020-01-23T21:30:09Z

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 · 2020-01-24T07:03:47Z

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

martijnvg · 2020-01-24T11:01:04Z

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.

* Only return history docs with state equal to executed * Sort by execution time instead of triggered time. * Don't auto box to boolean to avoid potential NPE. * Throw AE instead of using fail() methods for better readability. * Reformated the search request body. Relates to #32299

Relates to #32299

martijnvg · 2020-01-27T07:58:45Z

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

See #32299

Prior to the change the watcher index listener didn't implement the `postIndex(ShardId, Engine.Index, Engine.IndexResult)` method. This caused document level exceptions like VersionConflictEngineException to be ignored. This commit fixes this. The watcher indexing listener did implement the `postIndex(ShardId, Engine.Index, Exception)` method, but that only handles engine level exceptions. This change also unmutes the SmokeTestWatcherTestSuiteIT#testMonitorClusterHealth test again. Relates to elastic#32299

#51466) Prior to the change the watcher index listener didn't implement the `postIndex(ShardId, Engine.Index, Engine.IndexResult)` method. This caused document level exceptions like VersionConflictEngineException to be ignored. This commit fixes this. The watcher indexing listener did implement the `postIndex(ShardId, Engine.Index, Exception)` method, but that only handles engine level exceptions. This change also unmutes the SmokeTestWatcherTestSuiteIT#testMonitorClusterHealth test again. Relates to #32299

martijnvg · 2020-01-30T10:16:19Z

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.

andyb-elastic added >test-failure Triaged test failures from CI :Data Management/Watcher labels Jul 23, 2018

jasontedor assigned spinscale Jul 25, 2018

dnhatn mentioned this issue Aug 30, 2018

Integrates soft-deletes into Elasticsearch #33222

Merged

dnhatn added a commit to dnhatn/elasticsearch that referenced this issue Aug 30, 2018

TEST: Mute testMonitorClusterHealth

07faa0b

Tracked at elastic#32299

dnhatn added a commit that referenced this issue Aug 30, 2018

TEST: Mute testMonitorClusterHealth

0a43347

Tracked at #32299

tvernum self-assigned this Feb 20, 2019

tvernum mentioned this issue Feb 20, 2019

Enable smoke-test-watcher with logging #39169

Merged

romseygeek mentioned this issue Feb 25, 2019

Upgrade to lucene 8.0.0-snapshot-ff9509a8df #39350

Merged

tlrx added a commit that referenced this issue Feb 27, 2019

Mute SmokeTestWatcherTestSuiteIT.testMonitorClusterHealth()

69fe79a

Tracked in #32299

jakelandis mentioned this issue May 22, 2019

Meta: Fix Watcher Test Failures #42409

Closed

martijnvg assigned martijnvg and unassigned spinscale and tvernum Jan 14, 2020

martijnvg added a commit to martijnvg/elasticsearch that referenced this issue Jan 14, 2020

Unmute SmokeTestWatcherTestSuiteIT suite

181764b

Also adds `assertWatchCount(0)` snippet inside assertBusy(...) based on the findings in: elastic#32299 (comment) Relates to elastic#32299

martijnvg mentioned this issue Jan 14, 2020

Unmute SmokeTestWatcherTestSuiteIT suite #50973

Merged

martijnvg added a commit that referenced this issue Jan 16, 2020

Unmute SmokeTestWatcherTestSuiteIT suite (#50973)

633b06a

Also adds `assertWatchCount(0)` snippet inside assertBusy(...) based on the findings in: #32299 (comment) Relates to #32299

martijnvg added a commit that referenced this issue Jan 16, 2020

Muted test.

9158127

See #32299

martijnvg mentioned this issue Jan 21, 2020

Unmuted testMonitorClusterHealth test and added more logging. #51249

Merged

SivagurunathanV pushed a commit to SivagurunathanV/elasticsearch that referenced this issue Jan 23, 2020

Muted test.

a7c7f0e

See elastic#32299

martijnvg added a commit that referenced this issue Jan 24, 2020

Mute test #32299

d8fb8d7

martijnvg added a commit that referenced this issue Jan 24, 2020

Update smoke test watcher test suite with the changes in master branch.

53ac28e

Relates to #32299

martijnvg added a commit that referenced this issue Jan 27, 2020

Muted test

d1f33aa

See #32299

martijnvg mentioned this issue Jan 27, 2020

The watcher indexing listener didn't handle document level exceptions. #51466

Merged

martijnvg closed this as completed Jan 30, 2020

martijnvg mentioned this issue Feb 18, 2020

[CI] Incorrect watch count in watcher stats api in tests #52453

Closed

przemekwitek mentioned this issue Mar 2, 2020

SmokeTestWatcherTestSuiteIT.testMonitorClusterHealth failures on master #52995

Closed

codebrain mentioned this issue Apr 1, 2020

7.7.0 meta ticket (Part 3) elastic/elasticsearch-net#4534

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[ci] SmokeTestWatcherTestSuiteIT.testMonitorClusterHealth #32299

[ci] SmokeTestWatcherTestSuiteIT.testMonitorClusterHealth #32299

andyb-elastic commented Jul 23, 2018

elasticmachine commented Jul 23, 2018

andyb-elastic commented Jul 23, 2018

jasontedor commented Jul 25, 2018

dnhatn commented Aug 30, 2018

tvernum commented Feb 20, 2019

benwtrent commented Feb 21, 2019

tvernum commented Feb 21, 2019

tvernum commented Feb 22, 2019

tlrx commented Feb 27, 2019 •

edited

Loading

martijnvg commented Jan 16, 2020

polyfractal commented Jan 23, 2020

martijnvg commented Jan 24, 2020

martijnvg commented Jan 24, 2020

martijnvg commented Jan 27, 2020

martijnvg commented Jan 30, 2020

[ci] SmokeTestWatcherTestSuiteIT.testMonitorClusterHealth #32299

[ci] SmokeTestWatcherTestSuiteIT.testMonitorClusterHealth #32299

Comments

andyb-elastic commented Jul 23, 2018

elasticmachine commented Jul 23, 2018

andyb-elastic commented Jul 23, 2018

jasontedor commented Jul 25, 2018

dnhatn commented Aug 30, 2018

tvernum commented Feb 20, 2019

benwtrent commented Feb 21, 2019

tvernum commented Feb 21, 2019

tvernum commented Feb 22, 2019

tlrx commented Feb 27, 2019 • edited Loading

martijnvg commented Jan 16, 2020

polyfractal commented Jan 23, 2020

martijnvg commented Jan 24, 2020

martijnvg commented Jan 24, 2020

martijnvg commented Jan 27, 2020

martijnvg commented Jan 30, 2020

tlrx commented Feb 27, 2019 •

edited

Loading