BasicWatcherTests.testConditionSearchWithIndexedTemplate failure in CI

[romseygeek]

First failure today, doesn't reproduce:
https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+periodic/771/console

REPRODUCE WITH: ./gradlew :x-pack:plugin:watcher:unitTest \
  -Dtests.seed=4169EA92261BEB25 \
  -Dtests.class=org.elasticsearch.xpack.watcher.test.integration.BasicWatcherTests \
  -Dtests.method="testConditionSearchWithIndexedTemplate" \
  -Dtests.security.manager=true \
  -Dtests.locale=th-TH \
  -Dtests.timezone=America/Catamarca \
  -Dcompiler.java=11 \
  -Druntime.java=8

java.lang.AssertionError: could not find watch [_name] to trigger
Expected: is <true>
     but: was <false>
	at __randomizedtesting.SeedInfo.seed([4169EA92261BEB25:E5DEECB217D189AB]:0)
	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
	at org.junit.Assert.assertThat(Assert.java:956)
	at org.elasticsearch.xpack.watcher.test.AbstractWatcherIntegrationTestCase$TimeWarp.trigger(AbstractWatcherIntegrationTestCase.java:561)
	at org.elasticsearch.xpack.watcher.test.AbstractWatcherIntegrationTestCase$TimeWarp.trigger(AbstractWatcherIntegrationTestCase.java:551)
	at org.elasticsearch.xpack.watcher.test.integration.BasicWatcherTests.testConditionSearch(BasicWatcherTests.java:366)
	at org.elasticsearch.xpack.watcher.test.integration.BasicWatcherTests.testConditionSearchWithIndexedTemplate(BasicWatcherTests.java:234)

[elasticmachine]

Pinging @elastic/es-core-features

[romseygeek]

Here's the relevant excerpt from the logs:

07:08:40   1> [2562-02-22T04:08:33,467][INFO ][o.e.x.w.t.i.BasicWatcherTests] [testConditionSearchWithIndexedTemplate] before test
07:08:40   1> [2562-02-22T04:08:33,467][INFO ][o.e.x.w.t.i.BasicWatcherTests] [testConditionSearchWithIndexedTemplate] [BasicWatcherTests#testConditionSearchWithIndexedTemplate]: setting up test
07:08:40   1> [2562-02-22T04:08:33,484][INFO ][o.e.c.m.MetaDataIndexTemplateService] [node_s1] adding template [random_index_template] for index patterns [*]
07:08:40   1> [2562-02-22T04:08:33,515][INFO ][o.e.x.w.t.i.BasicWatcherTests] [testConditionSearchWithIndexedTemplate] [BasicWatcherTests#testConditionSearchWithIndexedTemplate]: all set up test
07:08:40   1> [2562-02-22T04:08:33,517][INFO ][o.e.x.w.t.i.BasicWatcherTests] [testConditionSearchWithIndexedTemplate] [BasicWatcherTests#testConditionSearchWithIndexedTemplate]: freezing time on nodes
07:08:40   1> [2562-02-22T04:08:33,522][INFO ][o.e.c.m.MetaDataCreateIndexService] [node_s1] [.watches] creating index, cause [api], templates [.watches, random_index_template], shards [2]/[0], mappings [doc]
07:08:40   1> [2562-02-22T04:08:33,523][INFO ][o.e.c.r.a.AllocationService] [node_s1] updating number_of_replicas to [1] for indices [.watches]
07:08:40   1> [2562-02-22T04:08:33,648][INFO ][o.e.c.m.MetaDataCreateIndexService] [node_s1] [.triggered_watches] creating index, cause [api], templates [.triggered_watches, random_index_template], shards [1]/[1], mappings [doc]
07:08:40   1> [2562-02-22T04:08:33,758][INFO ][o.e.c.m.MetaDataCreateIndexService] [node_s1] [.watcher-history-9-2019.02.22] creating index, cause [api], templates [.watch-history-9, random_index_template], shards [1]/[0], mappings [doc]
07:08:40   1> [2562-02-22T04:08:33,759][INFO ][o.e.c.r.a.AllocationService] [node_s1] updating number_of_replicas to [1] for indices [.watcher-history-9-2019.02.22]
07:08:40   1> [2562-02-22T04:08:33,862][INFO ][o.e.x.w.t.i.BasicWatcherTests] [testConditionSearchWithIndexedTemplate] creating watch history index [.watcher-history-9-2019.02.22]
07:08:40   1> [2562-02-22T04:08:33,939][INFO ][o.e.c.r.a.AllocationService] [node_s1] Cluster health status changed from [YELLOW] to [GREEN] (reason: [shards started [[.watcher-history-9-2019.02.22][0]] ...]).
07:08:40   1> [2562-02-22T04:08:33,963][DEBUG][o.e.x.w.t.i.BasicWatcherTests] [testConditionSearchWithIndexedTemplate] indices [.watcher-history-9-2019.02.22, .watches, .triggered_watches] are green
07:08:40   1> [2562-02-22T04:08:33,964][INFO ][o.e.x.w.t.i.BasicWatcherTests] [testConditionSearchWithIndexedTemplate] waiting to start watcher, current states [Tuple [v1=node_s0, v2=STOPPED], Tuple [v1=node_s1, v2=STOPPED], Tuple [v1=node_s2, v2=STOPPED]]
07:08:40   1> [2562-02-22T04:08:33,984][DEBUG][o.e.x.w.WatcherService   ] [node_s2] watch service has been reloaded, reason [starting]
07:08:40   1> [2562-02-22T04:08:33,985][INFO ][o.e.x.w.t.i.BasicWatcherTests] [testConditionSearchWithIndexedTemplate] waiting to start watcher, current states [Tuple [v1=node_s0, v2=STARTING], Tuple [v1=node_s1, v2=STARTING], Tuple [v1=node_s2, v2=STARTING]]
07:08:40   1> [2562-02-22T04:08:33,986][DEBUG][o.e.x.w.WatcherService   ] [node_s1] watch service has been reloaded, reason [starting]
07:08:40   1> [2562-02-22T04:08:33,986][DEBUG][o.e.x.w.WatcherService   ] [node_s0] watch service has been reloaded, reason [starting]
07:08:40   1> [2562-02-22T04:08:33,989][INFO ][o.e.x.w.t.i.BasicWatcherTests] [testConditionSearchWithIndexedTemplate] waiting to start watcher, current states [Tuple [v1=node_s0, v2=STARTED], Tuple [v1=node_s1, v2=STARTED], Tuple [v1=node_s2, v2=STARTED]]
07:08:40   1> [2562-02-22T04:08:34,069][INFO ][o.e.c.m.MetaDataCreateIndexService] [node_s1] [events] creating index, cause [api], templates [random_index_template], shards [4]/[1], mappings [event]
07:08:40   1> [2562-02-22T04:08:34,263][WARN ][o.e.d.x.w.s.s.WatcherSearchTemplateRequest] [testConditionSearchWithIndexedTemplate] [types removal] Specifying types in a watcher search request is deprecated.
07:08:40   1> [2562-02-22T04:08:34,267][DEBUG][o.e.x.w.WatcherIndexingListener] [node_s2] adding watch [_name] to trigger service
07:08:40   1> [2562-02-22T04:08:34,267][DEBUG][o.e.x.w.t.ScheduleTriggerEngineMock] [node_s2] adding watch [_name]
07:08:40   1> [2562-02-22T04:08:34,321][DEBUG][o.e.x.w.WatcherIndexingListener] [node_s1] watch [_name] should not be triggered
07:08:40   1> [2562-02-22T04:08:34,390][INFO ][o.e.x.w.t.i.BasicWatcherTests] [testConditionSearchWithIndexedTemplate] created watch [_name] at [2019-02-22T07:08:34.390Z]
07:08:40   1> [2562-02-22T04:08:34,457][INFO ][o.e.c.r.a.AllocationService] [node_s1] Cluster health status changed from [YELLOW] to [GREEN] (reason: [shards started [[events][0]] ...]).
07:08:40   1> [2562-02-22T04:08:34,467][INFO ][o.e.x.w.WatcherService   ] [node_s0] reloading watcher, reason [new local watcher shard allocation ids], cancelled [0] queued tasks
07:08:40   1> [2562-02-22T04:08:34,472][INFO ][o.e.x.w.WatcherService   ] [node_s2] reloading watcher, reason [new local watcher shard allocation ids], cancelled [0] queued tasks
07:08:40   1> [2562-02-22T04:08:34,492][INFO ][o.e.x.w.t.i.BasicWatcherTests] [testConditionSearchWithIndexedTemplate] [#testConditionSearchWithIndexedTemplate]: clearing watcher state
07:08:40   1> [2562-02-22T04:08:34,501][INFO ][o.e.x.w.t.i.BasicWatcherTests] [testConditionSearchWithIndexedTemplate] waiting to stop watcher, current states [Tuple [v1=node_s0, v2=STARTED], Tuple [v1=node_s1, v2=STARTED], Tuple [v1=node_s2, v2=STARTED]]
07:08:40   1> [2562-02-22T04:08:34,506][DEBUG][o.e.x.w.WatcherService   ] [node_s2] Loaded [1] watches for execution
07:08:40   1> [2562-02-22T04:08:34,507][DEBUG][o.e.x.w.t.ScheduleTriggerEngineMock] [node_s2] adding watch [_name]
07:08:40   1> [2562-02-22T04:08:34,507][DEBUG][o.e.x.w.WatcherService   ] [node_s2] watch service has been reloaded, reason [new local watcher shard allocation ids]
07:08:40   1> [2562-02-22T04:08:34,509][INFO ][o.e.x.w.WatcherService   ] [node_s2] stopping watch service, reason [watcher manually marked to shutdown by cluster state update]
07:08:40   1> [2562-02-22T04:08:34,522][INFO ][o.e.x.w.WatcherService   ] [node_s0] stopping watch service, reason [watcher manually marked to shutdown by cluster state update]
07:08:40   1> [2562-02-22T04:08:34,525][INFO ][o.e.x.w.WatcherService   ] [node_s1] stopping watch service, reason [watcher manually marked to shutdown by cluster state update]
07:08:40   1> [2562-02-22T04:08:34,525][DEBUG][o.e.x.w.WatcherService   ] [node_s0] Loaded [0] watches for execution
07:08:40   1> [2562-02-22T04:08:34,525][DEBUG][o.e.x.w.WatcherService   ] [node_s0] watch service has been reloaded, reason [new local watcher shard allocation ids]
07:08:40   1> [2562-02-22T04:08:34,537][INFO ][o.e.x.w.t.i.BasicWatcherTests] [testConditionSearchWithIndexedTemplate] waiting to stop watcher, current states [Tuple [v1=node_s0, v2=STOPPED], Tuple [v1=node_s1, v2=STOPPED], Tuple [v1=node_s2, v2=STOPPED]]
07:08:40   1> [2562-02-22T04:08:34,537][INFO ][o.e.x.w.t.i.BasicWatcherTests] [testConditionSearchWithIndexedTemplate] [BasicWatcherTests#testConditionSearchWithIndexedTemplate]: cleaning up after test
07:08:40   1> [2562-02-22T04:08:34,537][INFO ][o.e.t.InternalTestCluster] [testConditionSearchWithIndexedTemplate] Clearing active scheme time frozen, expected healing time 0s
07:08:40   1> [2562-02-22T04:08:34,621][INFO ][o.e.c.m.MetaDataDeleteIndexService] [node_s1] [events/nEflFtsKTxiX2BR5iWLQ7w] deleting index
07:08:40   1> [2562-02-22T04:08:34,621][INFO ][o.e.c.m.MetaDataDeleteIndexService] [node_s1] [.watcher-history-9-2019.02.22/vVuCZoyeTvOnn8psnI57jg] deleting index
07:08:40   1> [2562-02-22T04:08:34,621][INFO ][o.e.c.m.MetaDataDeleteIndexService] [node_s1] [.triggered_watches/GUvgZB-ZRS-meV2flQMNHQ] deleting index
07:08:40   1> [2562-02-22T04:08:34,621][INFO ][o.e.c.m.MetaDataDeleteIndexService] [node_s1] [.watches/ZZM3cuZ_RMuANl8X8ec09Q] deleting index
07:08:40   1> [2562-02-22T04:08:34,720][INFO ][o.e.c.m.MetaDataIndexTemplateService] [node_s1] removing template [random_index_template]
07:08:40   1> [2562-02-22T04:08:34,736][INFO ][o.e.x.w.t.i.BasicWatcherTests] [testConditionSearchWithIndexedTemplate] [BasicWatcherTests#testConditionSearchWithIndexedTemplate]: cleaned up after test
07:08:40   1> [2562-02-22T04:08:34,736][INFO ][o.e.x.w.t.i.BasicWatcherTests] [testConditionSearchWithIndexedTemplate] after test
07:08:40 FAILURE 1.31s J5 | BasicWatcherTests.testConditionSearchWithIndexedTemplate <<< FAILURES!
07:08:40    > Throwable #1: java.lang.AssertionError: could not find watch [_name] to trigger
07:08:40    > Expected: is <true>
07:08:40    >      but: was <false>
07:08:40    > 	at __randomizedtesting.SeedInfo.seed([4169EA92261BEB25:E5DEECB217D189AB]:0)
07:08:40    > 	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
07:08:40    > 	at org.elasticsearch.xpack.watcher.test.AbstractWatcherIntegrationTestCase$TimeWarp.trigger(AbstractWatcherIntegrationTestCase.java:561)
07:08:40    > 	at org.elasticsearch.xpack.watcher.test.AbstractWatcherIntegrationTestCase$TimeWarp.trigger(AbstractWatcherIntegrationTestCase.java:551)
07:08:40    > 	at org.elasticsearch.xpack.watcher.test.integration.BasicWatcherTests.testConditionSearch(BasicWatcherTests.java:366)
07:08:40    > 	at org.elasticsearch.xpack.watcher.test.integration.BasicWatcherTests.testConditionSearchWithIndexedTemplate(BasicWatcherTests.java:234)
07:08:40    > 	at java.lang.Thread.run(Thread.java:748)

[romseygeek]

When I run it locally, the watch fires immediately on being created, which doesn't seem to be happening here

[costin]

A similar issue : https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+periodic/790/console
However it might be a side effect of the InternalTestCluster not shutting down properly:

11:03:32   1> [2019-02-25T18:03:31,323][INFO ][o.e.t.InternalTestCluster] [testErrorInAction] Clearing active scheme time frozen, expected healing time 0s
11:03:32   1> [2019-02-25T18:03:31,469][INFO ][o.e.c.m.MetaDataDeleteIndexService] [node_s1] [.watches/q4i96OQBQs2UC0osGVx6Nw] deleting index
11:03:32   1> [2019-02-25T18:03:31,469][INFO ][o.e.c.m.MetaDataDeleteIndexService] [node_s1] [.watcher-history-9-2019.02.25/qEuFgiGpRFiWZut4vqG6sQ] deleting index
11:03:32   1> [2019-02-25T18:03:31,469][INFO ][o.e.c.m.MetaDataDeleteIndexService] [node_s1] [.triggered_watches/NWQgeAeLRtqXc7zsLaMVmQ] deleting index
11:03:32   1> [2019-02-25T18:03:31,469][INFO ][o.e.c.m.MetaDataDeleteIndexService] [node_s1] [foo/yzR5JWiKSwumN-CXyX1Bdg] deleting index
11:03:32   1> [2019-02-25T18:03:31,644][WARN ][o.e.i.c.IndicesClusterStateService] [node_s1] [[.watches][0]] marking and sending shard failed due to [failed recovery]
11:03:32   1> org.elasticsearch.indices.recovery.RecoveryFailedException: [.watches][0]: Recovery failed from {node_s0}{GHoh-uJ4TP2MJbHPPXxVWQ}{x8sbBnWuQQ-CgDsVj8De3w}{127.0.0.1}{127.0.0.1:34290}{xpack.installed=true} into {node_s1}{nuYSiub9Q-urxyOiL-sViw}{6_tc6rZWTnOZZw2d4fRwCg}{127.0.0.1}{127.0.0.1:45552}{xpack.installed=true} (failed to retry recovery)
11:03:32   1> 	at org.elasticsearch.indices.recovery.RecoveriesCollection.resetRecovery(RecoveriesCollection.java:121) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
11:03:32   1> 	at org.elasticsearch.indices.recovery.PeerRecoveryTargetService.retryRecovery(PeerRecoveryTargetService.java:165) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
11:03:32   1> 	at org.elasticsearch.indices.recovery.PeerRecoveryTargetService.retryRecovery(PeerRecoveryTargetService.java:161) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
11:03:32   1> 	at org.elasticsearch.indices.recovery.PeerRecoveryTargetService.lambda$doRecovery$2(PeerRecoveryTargetService.java:225) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
11:03:32   1> 	at org.elasticsearch.indices.recovery.PeerRecoveryTargetService$1.handleException(PeerRecoveryTargetService.java:298) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
11:03:32   1> 	at org.elasticsearch.transport.PlainTransportFuture.handleException(PlainTransportFuture.java:97) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
11:03:32   1> 	at org.elasticsearch.transport.TransportService$ContextRestoreResponseHandler.handleException(TransportService.java:1118) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
11:03:32   1> 	at org.elasticsearch.transport.TcpTransport.lambda$handleException$24(TcpTransport.java:1001) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
11:03:32   1> 	at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingRunnable.run(ThreadContext.java:681) [elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
11:03:32   1> 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_202]
11:03:32   1> 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_202]
11:03:32   1> 	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_202]
11:03:32   1> Caused by: java.lang.IllegalStateException: cannot reset recovery as previous attempt made it past finalization step
11:03:32   1> 	at org.elasticsearch.indices.recovery.RecoveryTarget.resetRecovery(RecoveryTarget.java:201) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
11:03:32   1> 	at org.elasticsearch.indices.recovery.RecoveriesCollection.resetRecovery(RecoveriesCollection.java:107) ~[elasticsearch-8.0.0-SNAPSHOT.jar:8.0.0-SNAPSHOT]
11:03:32   1> 	... 11 more
11:03:32   1> [2019-02-25T18:03:31,759][INFO ][o.e.c.m.MetaDataIndexTemplateService] [node_s1] removing template [random_index_template]
11:03:32   1> [2019-02-25T18:03:31,791][INFO ][o.e.x.w.a.ActionErrorIntegrationTests] [testErrorInAction] [ActionErrorIntegrationTests#testErrorInAction]: cleaned up after test
11:03:32   1> [2019-02-25T18:03:31,791][INFO ][o.e.x.w.a.ActionErrorIntegrationTests] [testErrorInAction] after test
11:03:32 FAILURE 3.60s J0 | ActionErrorIntegrationTests.testErrorInAction <<< FAILURES!
11:03:32    > Throwable #1: java.lang.AssertionError: could not find watch [_id] to trigger

[jtibshirani]

I'm closing this now that #39724 has merged. It similar failures pop up again, feel free to reopen the main issue #35503 where these errors are being tracked.