[CI] ActivateWatchTests.testDeactivateAndActivate needs to not be sleep based

[rjernst]

Because this test is sleep based, it can lead to failures on slow or overloaded machines. Eg:
https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+6.x+multijob-unix-compatibility/os=fedora/1064/console

This needs to be rewritten to not be sleep based.

[elasticmachine]

Pinging @elastic/es-core-infra

[jasontedor]

@hub-cap Can you take a look? I am happy to discuss.

[hub-cap]

Im adding the logs because its quite likely this will disappear over time.

  1> [0030-05-16T23:11:35,675][INFO ][o.e.n.Node               ] [node_s1] started
  1> [0030-05-16T23:11:35,732][DEBUG][o.e.x.w.s.WatcherIndexTemplateRegistry] [node_s1] adding index template [.triggered_watches], because it doesn't exist
  1> [0030-05-16T23:11:35,732][DEBUG][o.e.x.w.s.WatcherIndexTemplateRegistry] [node_s1] adding index template [.watch-history-7], because it doesn't exist
  1> [0030-05-16T23:11:35,732][DEBUG][o.e.x.w.s.WatcherIndexTemplateRegistry] [node_s1] adding index template [.watches], because it doesn't exist
  1> [0030-05-16T23:11:35,733][INFO ][o.e.g.GatewayService     ] [node_s1] recovered [0] indices into cluster_state
  1> [0030-05-16T23:11:35,737][INFO ][o.e.c.m.MetaDataIndexTemplateService] [node_s1] adding template [.triggered_watches] for index patterns [.triggered_watches*]
  1> [0030-05-16T23:11:35,750][INFO ][o.e.c.m.MetaDataIndexTemplateService] [node_s1] adding template [.watch-history-7] for index patterns [.watcher-history-7*]
  1> [0030-05-16T23:11:35,759][INFO ][o.e.c.m.MetaDataIndexTemplateService] [node_s1] adding template [.watches] for index patterns [.watches*]
  1> [0030-05-16T23:11:36,040][INFO ][o.e.l.LicenseService     ] [node_s0] license [9ec38660-b86b-40e8-b0a1-44bb82b00b64] mode [trial] - valid
  1> [0030-05-16T23:11:36,216][INFO ][o.e.l.LicenseService     ] [node_s1] license [9ec38660-b86b-40e8-b0a1-44bb82b00b64] mode [trial] - valid
  1> [0030-05-16T23:11:36,222][INFO ][o.e.c.m.MetaDataIndexTemplateService] [node_s1] adding template [random_index_template] for index patterns [*]
  1> [0030-05-16T23:11:36,235][INFO ][o.e.x.w.t.a.a.ActivateWatchTests] [ActivateWatchTests#testDeactivateAndActivate]: all set up test
  1> [0030-05-16T23:11:36,240][INFO ][o.e.c.m.MetaDataCreateIndexService] [node_s1] [.watches] creating index, cause [api], templates [.watches, random_index_template], shards [2]/[0], mappings [doc]
  1> [0030-05-16T23:11:36,240][INFO ][o.e.c.r.a.AllocationService] [node_s1] updating number_of_replicas to [1] for indices [.watches]
  1> [0030-05-16T23:11:36,420][INFO ][o.e.c.m.MetaDataCreateIndexService] [node_s1] [.triggered_watches] creating index, cause [api], templates [.triggered_watches, random_index_template], shards [1]/[0], mappings [doc]
  1> [0030-05-16T23:11:36,421][INFO ][o.e.c.r.a.AllocationService] [node_s1] updating number_of_replicas to [1] for indices [.triggered_watches]
  1> [0030-05-16T23:11:36,574][INFO ][o.e.c.m.MetaDataCreateIndexService] [node_s1] [.watcher-history-7-2018.05.17] creating index, cause [api], templates [.watch-history-7, random_index_template], shards [1]/[0], mappings [doc]
  1> [0030-05-16T23:11:36,574][INFO ][o.e.c.r.a.AllocationService] [node_s1] updating number_of_replicas to [1] for indices [.watcher-history-7-2018.05.17]
  1> [0030-05-16T23:11:36,664][INFO ][o.e.x.w.t.a.a.ActivateWatchTests] creating watch history index [.watcher-history-7-2018.05.17]
  1> [0030-05-16T23:11:36,735][INFO ][o.e.c.r.a.AllocationService] [node_s1] Cluster health status changed from [YELLOW] to [GREEN] (reason: [shards started [[.watcher-history-7-2018.05.17][0]] ...]).
  1> [0030-05-16T23:11:36,742][DEBUG][o.e.x.w.t.a.a.ActivateWatchTests] indices [.watcher-history-7-2018.05.17, .watches, .triggered_watches] are green
  1> [0030-05-16T23:11:36,743][INFO ][o.e.x.w.t.a.a.ActivateWatchTests] waiting to start watcher, current states [Tuple [v1=node_s1, v2=STARTED], Tuple [v1=node_s0, v2=STARTED]]
  1> [0030-05-16T23:11:36,768][DEBUG][o.e.x.w.WatcherIndexingListener] [node_s1] adding watch [_id] to trigger service
  1> [0030-05-16T23:11:36,825][DEBUG][o.e.x.w.WatcherIndexingListener] [node_s0] watch [_id] should not be triggered
  1> [0030-05-16T23:11:36,903][INFO ][o.e.x.w.t.a.a.ActivateWatchTests] Waiting for watch to be executed at least once
  1> [0030-05-16T23:11:37,821][DEBUG][o.e.x.w.t.s.e.TickerScheduleTriggerEngine] [node_s1] triggered job [_id] at [2018-05-17T08:41:37.821Z] (scheduled time was [2018-05-17T08:41:37.768Z])
  1> [0030-05-16T23:11:37,875][DEBUG][o.e.x.w.e.ExecutionService] [node_s1] executing watch [_id]
  1> [0030-05-16T23:11:37,881][INFO ][o.e.c.m.MetaDataCreateIndexService] [node_s1] [actions] creating index, cause [auto(bulk api)], templates [random_index_template], shards [7]/[0], mappings []
  1> [0030-05-16T23:11:38,218][INFO ][o.e.c.r.a.AllocationService] [node_s1] Cluster health status changed from [YELLOW] to [GREEN] (reason: [shards started [[actions][1]] ...]).
  1> [0030-05-16T23:11:38,232][INFO ][o.e.c.m.MetaDataMappingService] [node_s1] [actions/hNl-YuA4QeCc_0n50OTh7Q] create_mapping [action1]
  1> [0030-05-16T23:11:38,297][DEBUG][o.e.x.w.WatcherIndexingListener] [node_s1] adding watch [_id] to trigger service
  1> [0030-05-16T23:11:38,338][DEBUG][o.e.x.w.WatcherIndexingListener] [node_s0] watch [_id] should not be triggered
  1> [0030-05-16T23:11:38,365][INFO ][o.e.c.m.MetaDataMappingService] [node_s1] [.watcher-history-7-2018.05.17/cqrtFbcaTE6aYRZRLB-JYw] update_mapping [doc]
  1> [0030-05-16T23:11:38,417][DEBUG][o.e.x.w.h.HistoryStore   ] [node_s1] indexed watch history record [_id_1ca5ba84-0a91-4767-9352-c647722ee3c9-2018-05-17T08:41:37.821Z]
  1> [0030-05-16T23:11:38,417][DEBUG][o.e.x.w.e.ExecutionService] [node_s1] finished [_id]/[_id_1ca5ba84-0a91-4767-9352-c647722ee3c9-2018-05-17T08:41:37.821Z]
  1> [0030-05-16T23:11:39,377][DEBUG][o.e.x.w.t.s.e.TickerScheduleTriggerEngine] [node_s1] triggered job [_id] at [2018-05-17T08:41:39.377Z] (scheduled time was [2018-05-17T08:41:39.303Z])
  1> [0030-05-16T23:11:39,448][DEBUG][o.e.x.w.e.ExecutionService] [node_s1] executing watch [_id]
  1> [0030-05-16T23:11:39,483][DEBUG][o.e.x.w.WatcherIndexingListener] [node_s1] removing watch [_id] to trigger service
  1> [0030-05-16T23:11:39,484][DEBUG][o.e.x.w.WatcherIndexingListener] [node_s1] adding watch [_id] to trigger service
  1> [0030-05-16T23:11:39,494][DEBUG][o.e.x.w.e.ExecutionService] [node_s1] failed to execute watch [_id]
  1> org.elasticsearch.index.engine.VersionConflictEngineException: [doc][_id]: version conflict, current version [3] is different than the one provided [2]
  1> 	at org.elasticsearch.index.engine.InternalEngine.planIndexingAsPrimary(InternalEngine.java:931) ~[elasticsearch-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
  1> 	at org.elasticsearch.index.engine.InternalEngine.index(InternalEngine.java:798) ~[elasticsearch-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
  1> 	at org.elasticsearch.index.shard.IndexShard.index(IndexShard.java:724) ~[elasticsearch-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
  1> 	at org.elasticsearch.index.shard.IndexShard.applyIndexOperation(IndexShard.java:693) ~[elasticsearch-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
  1> 	at org.elasticsearch.index.shard.IndexShard.applyIndexOperationOnPrimary(IndexShard.java:658) ~[elasticsearch-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
  1> 	at org.elasticsearch.action.bulk.TransportShardBulkAction.lambda$executeIndexRequestOnPrimary$2(TransportShardBulkAction.java:569) ~[elasticsearch-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
  1> 	at org.elasticsearch.action.bulk.TransportShardBulkAction.executeOnPrimaryWhileHandlingMappingUpdates(TransportShardBulkAction.java:588) ~[elasticsearch-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
  1> 	at org.elasticsearch.action.bulk.TransportShardBulkAction.executeIndexRequestOnPrimary(TransportShardBulkAction.java:567) ~[elasticsearch-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
  1> 	at org.elasticsearch.action.bulk.TransportShardBulkAction.executeIndexRequest(TransportShardBulkAction.java:142) ~[elasticsearch-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
  1> 	at org.elasticsearch.action.bulk.TransportShardBulkAction.executeBulkItemRequest(TransportShardBulkAction.java:248) ~[elasticsearch-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
  1> 	at org.elasticsearch.action.bulk.TransportShardBulkAction.performOnPrimary(TransportShardBulkAction.java:125) ~[elasticsearch-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
  1> 	at org.elasticsearch.action.bulk.TransportShardBulkAction.shardOperationOnPrimary(TransportShardBulkAction.java:112) ~[elasticsearch-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
  1> 	at org.elasticsearch.action.bulk.TransportShardBulkAction.shardOperationOnPrimary(TransportShardBulkAction.java:74) ~[elasticsearch-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
  1> 	at org.elasticsearch.action.support.replication.TransportReplicationAction$PrimaryShardReference.perform(TransportReplicationAction.java:1018) ~[elasticsearch-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
  1> 	at org.elasticsearch.action.support.replication.TransportReplicationAction$PrimaryShardReference.perform(TransportReplicationAction.java:996) ~[elasticsearch-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
  1> 	at org.elasticsearch.action.support.replication.ReplicationOperation.execute(ReplicationOperation.java:103) ~[elasticsearch-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
  1> 	at org.elasticsearch.action.support.replication.TransportReplicationAction$AsyncPrimaryAction.onResponse(TransportReplicationAction.java:357) ~[elasticsearch-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
  1> 	at org.elasticsearch.action.support.replication.TransportReplicationAction$AsyncPrimaryAction.onResponse(TransportReplicationAction.java:297) ~[elasticsearch-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
  1> 	at org.elasticsearch.action.support.replication.TransportReplicationAction$1.onResponse(TransportReplicationAction.java:959) ~[elasticsearch-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
  1> 	at org.elasticsearch.action.support.replication.TransportReplicationAction$1.onResponse(TransportReplicationAction.java:956) ~[elasticsearch-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
  1> 	at org.elasticsearch.index.shard.IndexShardOperationPermits.acquire(IndexShardOperationPermits.java:270) ~[elasticsearch-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
  1> 	at org.elasticsearch.index.shard.IndexShardOperationPermits.acquire(IndexShardOperationPermits.java:237) ~[elasticsearch-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
  1> 	at org.elasticsearch.index.shard.IndexShard.acquirePrimaryOperationPermit(IndexShard.java:2213) ~[elasticsearch-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
  1> 	at org.elasticsearch.action.support.replication.TransportReplicationAction.acquirePrimaryShardReference(TransportReplicationAction.java:968) ~[elasticsearch-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
  1> 	at org.elasticsearch.action.support.replication.TransportReplicationAction.access$500(TransportReplicationAction.java:98) ~[elasticsearch-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
  1> 	at org.elasticsearch.action.support.replication.TransportReplicationAction$AsyncPrimaryAction.doRun(TransportReplicationAction.java:318) ~[elasticsearch-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
  1> 	at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37) ~[elasticsearch-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
  1> 	at org.elasticsearch.action.support.replication.TransportReplicationAction$PrimaryOperationTransportHandler.messageReceived(TransportReplicationAction.java:293) ~[elasticsearch-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
  1> 	at org.elasticsearch.action.support.replication.TransportReplicationAction$PrimaryOperationTransportHandler.messageReceived(TransportReplicationAction.java:280) ~[elasticsearch-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
  1> 	at org.elasticsearch.transport.RequestHandlerRegistry.processMessageReceived(RequestHandlerRegistry.java:66) ~[elasticsearch-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
  1> 	at org.elasticsearch.transport.TransportService$7.doRun(TransportService.java:656) ~[elasticsearch-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
  1> 	at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:724) ~[elasticsearch-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
  1> 	at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37) ~[elasticsearch-6.4.0-SNAPSHOT.jar:6.4.0-SNAPSHOT]
  1> 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_162]
  1> 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_162]
  1> 	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_162]
  1> [0030-05-16T23:11:39,526][DEBUG][o.e.x.w.h.HistoryStore   ] [node_s1] indexed watch history record [_id_02ec1a21-0eb2-462b-a2ac-4df36490d5d1-2018-05-17T08:41:39.377Z]
  1> [0030-05-16T23:11:39,527][DEBUG][o.e.x.w.e.ExecutionService] [node_s1] finished [_id]/[_id_02ec1a21-0eb2-462b-a2ac-4df36490d5d1-2018-05-17T08:41:39.377Z]
  1> [0030-05-16T23:11:39,627][DEBUG][o.e.x.w.WatcherIndexingListener] [node_s0] watch [_id] should not be triggered
  1> [0030-05-16T23:11:39,701][INFO ][o.e.x.w.t.a.a.ActivateWatchTests] Ensured no more watches are being executed
  1> [0030-05-16T23:11:40,137][INFO ][o.e.x.w.t.a.a.ActivateWatchTests] Sleeping for 5 seconds, watch history count [2]
  1> [0030-05-16T23:11:40,885][DEBUG][o.e.x.w.t.s.e.TickerScheduleTriggerEngine] [node_s1] triggered job [_id] at [2018-05-17T08:41:40.885Z] (scheduled time was [2018-05-17T08:41:40.484Z])
  1> [0030-05-16T23:11:40,900][DEBUG][o.e.x.w.e.ExecutionService] [node_s1] not executing watch [_id]
  1> [0030-05-16T23:11:40,930][DEBUG][o.e.x.w.h.HistoryStore   ] [node_s1] indexed watch history record [_id_abf3ff21-3a67-4e15-9ab2-9d19d60f423a-2018-05-17T08:41:40.886Z]
  1> [0030-05-16T23:11:40,931][DEBUG][o.e.x.w.e.ExecutionService] [node_s1] finished [_id]/[_id_abf3ff21-3a67-4e15-9ab2-9d19d60f423a-2018-05-17T08:41:40.886Z]
  1> [0030-05-16T23:11:41,887][DEBUG][o.e.x.w.t.s.e.TickerScheduleTriggerEngine] [node_s1] triggered job [_id] at [2018-05-17T08:41:41.887Z] (scheduled time was [2018-05-17T08:41:41.484Z])
  1> [0030-05-16T23:11:41,898][DEBUG][o.e.x.w.e.ExecutionService] [node_s1] not executing watch [_id]
  1> [0030-05-16T23:11:41,917][DEBUG][o.e.x.w.h.HistoryStore   ] [node_s1] indexed watch history record [_id_10796f1d-24d7-4641-a476-e4636e36314e-2018-05-17T08:41:41.888Z]
  1> [0030-05-16T23:11:41,918][DEBUG][o.e.x.w.e.ExecutionService] [node_s1] finished [_id]/[_id_10796f1d-24d7-4641-a476-e4636e36314e-2018-05-17T08:41:41.888Z]
  1> [0030-05-16T23:11:42,889][DEBUG][o.e.x.w.t.s.e.TickerScheduleTriggerEngine] [node_s1] triggered job [_id] at [2018-05-17T08:41:42.889Z] (scheduled time was [2018-05-17T08:41:42.484Z])
  1> [0030-05-16T23:11:42,896][DEBUG][o.e.x.w.e.ExecutionService] [node_s1] not executing watch [_id]
  1> [0030-05-16T23:11:42,916][DEBUG][o.e.x.w.h.HistoryStore   ] [node_s1] indexed watch history record [_id_01f560b6-3fb0-4f0c-9fe3-ba484294d68c-2018-05-17T08:41:42.889Z]
  1> [0030-05-16T23:11:42,916][DEBUG][o.e.x.w.e.ExecutionService] [node_s1] finished [_id]/[_id_01f560b6-3fb0-4f0c-9fe3-ba484294d68c-2018-05-17T08:41:42.889Z]
  1> [0030-05-16T23:11:43,890][DEBUG][o.e.x.w.t.s.e.TickerScheduleTriggerEngine] [node_s1] triggered job [_id] at [2018-05-17T08:41:43.890Z] (scheduled time was [2018-05-17T08:41:43.484Z])
  1> [0030-05-16T23:11:43,895][DEBUG][o.e.x.w.e.ExecutionService] [node_s1] not executing watch [_id]
  1> [0030-05-16T23:11:43,906][DEBUG][o.e.x.w.h.HistoryStore   ] [node_s1] indexed watch history record [_id_97a15f56-5930-4e82-b458-e2b6b870ed61-2018-05-17T08:41:43.890Z]
  1> [0030-05-16T23:11:43,906][DEBUG][o.e.x.w.e.ExecutionService] [node_s1] finished [_id]/[_id_97a15f56-5930-4e82-b458-e2b6b870ed61-2018-05-17T08:41:43.890Z]
  1> [0030-05-16T23:11:44,892][DEBUG][o.e.x.w.t.s.e.TickerScheduleTriggerEngine] [node_s1] triggered job [_id] at [2018-05-17T08:41:44.892Z] (scheduled time was [2018-05-17T08:41:44.484Z])
  1> [0030-05-16T23:11:44,897][DEBUG][o.e.x.w.e.ExecutionService] [node_s1] not executing watch [_id]
  1> [0030-05-16T23:11:44,905][DEBUG][o.e.x.w.h.HistoryStore   ] [node_s1] indexed watch history record [_id_e4aee542-c8e5-4fba-9dde-2a9884437840-2018-05-17T08:41:44.892Z]
  1> [0030-05-16T23:11:44,905][DEBUG][o.e.x.w.e.ExecutionService] [node_s1] finished [_id]/[_id_e4aee542-c8e5-4fba-9dde-2a9884437840-2018-05-17T08:41:44.892Z]
  1> [0030-05-16T23:11:45,184][INFO ][o.e.x.w.t.a.a.ActivateWatchTests] [#testDeactivateAndActivate]: clearing watcher state
  1> [0030-05-16T23:11:45,185][INFO ][o.e.x.w.t.a.a.ActivateWatchTests] waiting to stop watcher, current states [Tuple [v1=node_s1, v2=STARTED], Tuple [v1=node_s0, v2=STARTED]]
  1> [0030-05-16T23:11:45,189][INFO ][o.e.x.w.WatcherService   ] [node_s0] stopping watch service, reason [watcher manually marked to shutdown by cluster state update]
  1> [0030-05-16T23:11:45,192][INFO ][o.e.x.w.WatcherService   ] [node_s1] stopping watch service, reason [watcher manually marked to shutdown by cluster state update]
  1> [0030-05-16T23:11:45,194][INFO ][o.e.x.w.t.a.a.ActivateWatchTests] waiting to stop watcher, current states [Tuple [v1=node_s1, v2=STOPPED], Tuple [v1=node_s0, v2=STOPPED]]
  1> [0030-05-16T23:11:45,195][INFO ][o.e.x.w.t.a.a.ActivateWatchTests] [ActivateWatchTests#testDeactivateAndActivate]: cleaning up after test
  1> [0030-05-16T23:11:45,213][INFO ][o.e.c.m.MetaDataDeleteIndexService] [node_s1] [.watcher-history-7-2018.05.17/cqrtFbcaTE6aYRZRLB-JYw] deleting index
  1> [0030-05-16T23:11:45,213][INFO ][o.e.c.m.MetaDataDeleteIndexService] [node_s1] [actions/hNl-YuA4QeCc_0n50OTh7Q] deleting index
  1> [0030-05-16T23:11:45,213][INFO ][o.e.c.m.MetaDataDeleteIndexService] [node_s1] [.triggered_watches/kEV-bkZoTOasgYLDdGBZUg] deleting index
  1> [0030-05-16T23:11:45,213][INFO ][o.e.c.m.MetaDataDeleteIndexService] [node_s1] [.watches/a0PftyaGQKCi3mJSP0RuJA] deleting index
  1> [0030-05-16T23:11:45,286][INFO ][o.e.c.m.MetaDataIndexTemplateService] [node_s1] removing template [random_index_template]
  1> [0030-05-16T23:11:45,292][INFO ][o.e.x.w.t.a.a.ActivateWatchTests] [ActivateWatchTests#testDeactivateAndActivate]: cleaned up after test
  1> [0030-05-16T23:11:45,292][INFO ][o.e.x.w.t.a.a.ActivateWatchTests] [testDeactivateAndActivate]: after test
  2> REPRODUCE WITH: ./gradlew :x-pack:plugin:watcher:test -Dtests.seed=35E260511772D8B6 -Dtests.class=org.elasticsearch.xpack.watcher.transport.action.activate.ActivateWatchTests -Dtests.method="testDeactivateAndActivate" -Dtests.security.manager=true -Dtests.locale=ja-JP-u-ca-japanese-x-lvariant-JP -Dtests.timezone=Pacific/Marquesas
FAILURE 10.5s J1 | ActivateWatchTests.testDeactivateAndActivate <<< FAILURES!
   > Throwable #1: java.lang.AssertionError: 
   > Expected: is <2L>
   >      but: was <7L>
   > 	at __randomizedtesting.SeedInfo.seed([35E260511772D8B6:95BA18ACD82B0ECA]:0)
   > 	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
   > 	at org.elasticsearch.xpack.watcher.transport.action.activate.ActivateWatchTests.testDeactivateAndActivate(ActivateWatchTests.java:97)
   > 	at java.lang.Thread.run(Thread.java:748)```

[hub-cap]

Something interesting to note is that when I attempt to run this and slow it down with a debugger, i can repro the conflict (and I believe that there is code to retry on conflict), but i always see the following line after.

2018-05-30T23:42:13,433][DEBUG][o.e.x.w.e.ExecutionService] [node_sd4] executing watch [_id]
[2018-05-30T23:42:13,441][DEBUG][o.e.x.w.h.HistoryStore   ] [node_sd4] indexed watch history record [_id_6e92b1ac-7781-49c3-8c51-7fee439b1c21-2018-05-30T17:56:53.753Z]
...

Whereas with the logs above, the "executing watch..." is not present.

edit

I was wrong, it is up there,

  1> [0030-05-16T23:11:37,875][DEBUG][o.e.x.w.e.ExecutionService] [node_s1] executing watch [_id]

[spinscale]

so, I stared at this test and its output a bit today, and I think the most important lines are the following:

39,448][DEBUG][o.e.x.w.e.ExecutionService] [node_s1] executing watch [_id]
39,483][DEBUG][o.e.x.w.WatcherIndexingListener] [node_s1] removing watch [_id] to trigger service
39,484][DEBUG][o.e.x.w.WatcherIndexingListener] [node_s1] adding watch [_id] to trigger service
39,494][DEBUG][o.e.x.w.e.ExecutionService] [node_s1] failed to execute watch [_id]
 org.elasticsearch.index.engine.VersionConflictEngineException: [doc][_id]: version conflict, current version [3] is different than the one provided [2]

What happens here, is that the deactivate watch action first removes the watch from the trigger service. However, then the ExecutionService.updateWatchStatus() method is called and adds the watch back to the trigger service. However the index operation fails due to a version conflict exception.

The WatcherIndexingListener.postIndex(ShardId, Engine.Index, Exception) logging message is never logged, which means to me that in the mean time this node lost the authority (because the shard might have been moved to another node) over the local watcher shard and thus triggerService.remove() is never called.

This brings the question, if the postIndex method is the right place for this or if this should be executed in the caller code depending on success or failure, because that triggerservice.remove() might only make sense if put watch action, a ack watch or a activate watch action is executed, but not if the execution service is called. This requires some more thinking (and also a lot of this is speculation because it is super hard to reproduce this bug so far).

Just as a side note: This does not mean that watches are executed more often than needed, because the watch is still not active, it only creates additional watch records telling that the watch is not active - which is why the failing assertion occurs.

[tvernum]

@hub-cap Are you still working on this?
I have a plan for how to rework it to avoid the sleep and skip the inactive watch records, if you don't have something in progress.

[hub-cap]

I do not have anything in progress here @tvernum. this fell off my radar a while ago :) Feel free to reassign it if you have something that will fix/close it.