Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[CI] ExecutionVarsIntegrationTests.testVars is failing #65086

Closed
valeriy42 opened this issue Nov 16, 2020 · 2 comments
Closed

[CI] ExecutionVarsIntegrationTests.testVars is failing #65086

valeriy42 opened this issue Nov 16, 2020 · 2 comments
Labels
:Data Management/Watcher Team:Data Management Meta label for data/management team >test-failure Triaged test failures from CI

Comments

@valeriy42
Copy link
Contributor

Build scan: https://gradle-enterprise.elastic.co/s/tuvmklzs2rtwa

Repro line:

./gradlew ':x-pack:plugin:watcher:internalClusterTest' --tests "org.elasticsearch.xpack.watcher.test.integration.ExecutionVarsIntegrationTests.testVars" -Dtests.seed=6B876C3C963351CB -Dtests.security.manager=true -Dtests.locale=ar-AE -Dtests.timezone=Pacific/Truk -Druntime.java=11

Reproduces locally?: No

Applicable branches: master

Failure history: build stats

Failure excerpt:

org.elasticsearch.xpack.watcher.test.integration.ExecutionVarsIntegrationTests > testVars FAILED
    java.lang.AssertionError: watch was triggered on [0] schedulers, expected [1]
    Expected: a value equal to or greater than <1L>
         but: <0L> was less than <1L>
        at __randomizedtesting.SeedInfo.seed([6B876C3C963351CB:BFCC74669B86D5C8]:0)
        at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:18)
        at org.junit.Assert.assertThat(Assert.java:956)
        at org.elasticsearch.xpack.watcher.test.AbstractWatcherIntegrationTestCase$TimeWarp.trigger(AbstractWatcherIntegrationTestCase.java:606)
        at org.elasticsearch.xpack.watcher.test.AbstractWatcherIntegrationTestCase$TimeWarp.trigger(AbstractWatcherIntegrationTestCase.java:591)
        at org.elasticsearch.xpack.watcher.test.integration.ExecutionVarsIntegrationTests.testVars(ExecutionVarsIntegrationTests.java:131)
REPRODUCE WITH: ./gradlew ':x-pack:plugin:watcher:internalClusterTest' --tests "org.elasticsearch.xpack.watcher.test.integration.ExecutionVarsIntegrationTests.testVars" -Dtests.seed=6B876C3C963351CB -Dtests.security.manager=true -Dtests.locale=ar-AE -Dtests.timezone=Pacific/Truk -Druntime.java=11

Suite: Test class org.elasticsearch.xpack.watcher.test.integration.ExecutionVarsIntegrationTests
  1> [2020-11-17T00:22:56,892][INFO ][o.e.x.w.t.i.ExecutionVarsIntegrationTests] [testVarsManual] before test
  1> [2020-11-17T00:22:56,911][INFO ][o.e.x.w.t.i.ExecutionVarsIntegrationTests] [testVarsManual] [ExecutionVarsIntegrationTests#testVarsManual]: setting up test
  1> [2020-11-17T00:22:56,989][INFO ][o.e.t.InternalTestCluster] [testVarsManual] Setup InternalTestCluster [SUITE-TEST_WORKER_VM=[537]-CLUSTER_SEED=[-3581282154539098659]-HASH=[1309DA1142A]-cluster] with seed [CE4CBADADA405DDD] using [1] dedicated masters, [3] (data) nodes and [0] coord only nodes (master nodes are [auto-managed])
  1> [2020-11-17T00:22:57,899][INFO ][o.e.n.Node               ] [testVarsManual] version[8.0.0-SNAPSHOT], pid[139975], build[unknown/unknown/923b2b90c5d06ae1a1e26211a1ded65750d2ee58/2020-11-16T14:02:35.834120Z], OS[Linux/5.4.0-1028-gcp/amd64], JVM[Oracle Corporation/OpenJDK 64-Bit Server VM/11.0.2/11.0.2+7]
  1> [2020-11-17T00:22:57,900][INFO ][o.e.n.Node               ] [testVarsManual] JVM home [/var/lib/jenkins/.java/openjdk-11.0.2-linux]
  1> [2020-11-17T00:22:57,910][DEPRECATION][o.e.d.n.Node             ] [testVarsManual] data_stream.dataset="deprecation.elasticsearch" data_stream.namespace="default" data_stream.type="logs" ecs.version="1.6" key="no-jdk" message="no-jdk distributions that do not bundle a JDK are deprecated and will be removed in a future release"
  1> [2020-11-17T00:22:57,911][INFO ][o.e.n.Node               ] [testVarsManual] JVM arguments [-Dfile.encoding=UTF8, -Des.scripting.update.ctx_in_params=false, -Des.search.rewrite_sort=true, -Des.set.netty.runtime.available.processors=false, -Des.transport.cname_in_publish_address=true, -Dgradle.dist.lib=/var/lib/jenkins/.gradle/wrapper/dists/gradle-6.6.1-all/ejrtlte9hlw8v6ii20a9584rs/gradle-6.6.1/lib, -Dgradle.user.home=/var/lib/jenkins/.gradle, -Dgradle.worker.jar=/var/lib/jenkins/.gradle/caches/6.6.1/workerMain/gradle-worker.jar, -Dio.netty.noKeySetOptimization=true, -Dio.netty.noUnsafe=true, -Dio.netty.recycler.maxCapacityPerThread=0, -Djava.awt.headless=true, -Djava.locale.providers=SPI,COMPAT, -Djna.nosys=true, -Dorg.gradle.native=false, -Dtests.artifact=watcher, -Dtests.gradle=true, -Dtests.logger.level=WARN, -Dtests.security.manager=true, -Dtests.seed=6B876C3C963351CB, -Dtests.task=:x-pack:plugin:watcher:internalClusterTest, --illegal-access=warn, -XX:+HeapDumpOnOutOfMemoryError, -esa, -XX:HeapDumpPath=/dev/shm/elastic+elasticsearch+master+multijob+fast+part2/x-pack/plugin/watcher/build/heapdump, -Xms512m, -Xmx512m, -Dfile.encoding=UTF-8, -Djava.io.tmpdir=/dev/shm/elastic+elasticsearch+master+multijob+fast+part2/x-pack/plugin/watcher/build/testrun/internalClusterTest/temp, -Duser.country=US, -Duser.language=en, -Duser.variant, -ea]
  1> [2020-11-17T00:22:57,912][WARN ][o.e.n.Node               ] [testVarsManual] version [8.0.0-SNAPSHOT] is a pre-release version of Elasticsearch and is not suitable for production
  1> [2020-11-17T00:22:57,947][INFO ][o.e.x.w.t.TimeWarpedWatcher] [testVarsManual] using time warped watchers plugin
  1> [2020-11-17T00:22:57,981][INFO ][o.e.p.PluginsService     ] [testVarsManual] no modules loaded
  1> [2020-11-17T00:22:57,983][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.analysis.common.CommonAnalysisPlugin]
  1> [2020-11-17T00:22:57,984][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.script.MockMustacheScriptEngine$TestPlugin]
  1> [2020-11-17T00:22:57,984][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.script.MockScriptService$TestPlugin]
  1> [2020-11-17T00:22:57,985][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.test.ESIntegTestCase$AssertActionNamePlugin]
  1> [2020-11-17T00:22:57,985][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.test.ESIntegTestCase$TestSeedPlugin]
  1> [2020-11-17T00:22:57,986][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.test.MockHttpTransport$TestPlugin]
  1> [2020-11-17T00:22:57,986][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.test.TestGeoShapeFieldMapperPlugin]
  1> [2020-11-17T00:22:57,987][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.test.store.MockFSIndexStore$TestPlugin]
  1> [2020-11-17T00:22:57,987][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.transport.nio.MockNioTransportPlugin]
  1> [2020-11-17T00:22:57,988][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.xpack.datastreams.DataStreamsPlugin]
  1> [2020-11-17T00:22:57,989][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.xpack.ilm.IndexLifecycle]
  1> [2020-11-17T00:22:57,989][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.xpack.watcher.test.TimeWarpedWatcher]
  1> [2020-11-17T00:22:57,989][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.xpack.watcher.test.integration.ExecutionVarsIntegrationTests$CustomScriptPlugin]
  1> [2020-11-17T00:22:58,083][INFO ][o.e.e.NodeEnvironment    ] [testVarsManual] using [1] data paths, mounts [[/dev/shm (tmpfs)]], net usable_space [44.1gb], net total_space [47.1gb], types [tmpfs]
  1> [2020-11-17T00:22:58,084][INFO ][o.e.e.NodeEnvironment    ] [testVarsManual] heap size [512mb], compressed ordinary object pointers [true]
  1> [2020-11-17T00:22:58,167][INFO ][o.e.n.Node               ] [testVarsManual] node name [node_s0], node ID [7CguAlnHTV-nFWMuwaxa3Q], cluster name [SUITE-TEST_WORKER_VM=[537]-CLUSTER_SEED=[-3581282154539098659]-HASH=[1309DA1142A]-cluster], roles [master, remote_cluster_client, ingest]
  1> [2020-11-17T00:23:03,638][INFO ][o.e.d.DiscoveryModule    ] [testVarsManual] using discovery type [zen] and seed hosts providers [settings, file]
  1> [2020-11-17T00:23:05,069][INFO ][o.e.n.Node               ] [testVarsManual] initialized
  1> [2020-11-17T00:23:05,075][INFO ][o.e.n.Node               ] [testVarsManual] version[8.0.0-SNAPSHOT], pid[139975], build[unknown/unknown/923b2b90c5d06ae1a1e26211a1ded65750d2ee58/2020-11-16T14:02:35.834120Z], OS[Linux/5.4.0-1028-gcp/amd64], JVM[Oracle Corporation/OpenJDK 64-Bit Server VM/11.0.2/11.0.2+7]
  1> [2020-11-17T00:23:05,075][INFO ][o.e.n.Node               ] [testVarsManual] JVM home [/var/lib/jenkins/.java/openjdk-11.0.2-linux]
  1> [2020-11-17T00:23:05,077][DEPRECATION][o.e.d.n.Node             ] [testVarsManual] data_stream.dataset="deprecation.elasticsearch" data_stream.namespace="default" data_stream.type="logs" ecs.version="1.6" key="no-jdk" message="no-jdk distributions that do not bundle a JDK are deprecated and will be removed in a future release"
  1> [2020-11-17T00:23:05,096][INFO ][o.e.n.Node               ] [testVarsManual] JVM arguments [-Dfile.encoding=UTF8, -Des.scripting.update.ctx_in_params=false, -Des.search.rewrite_sort=true, -Des.set.netty.runtime.available.processors=false, -Des.transport.cname_in_publish_address=true, -Dgradle.dist.lib=/var/lib/jenkins/.gradle/wrapper/dists/gradle-6.6.1-all/ejrtlte9hlw8v6ii20a9584rs/gradle-6.6.1/lib, -Dgradle.user.home=/var/lib/jenkins/.gradle, -Dgradle.worker.jar=/var/lib/jenkins/.gradle/caches/6.6.1/workerMain/gradle-worker.jar, -Dio.netty.noKeySetOptimization=true, -Dio.netty.noUnsafe=true, -Dio.netty.recycler.maxCapacityPerThread=0, -Djava.awt.headless=true, -Djava.locale.providers=SPI,COMPAT, -Djna.nosys=true, -Dorg.gradle.native=false, -Dtests.artifact=watcher, -Dtests.gradle=true, -Dtests.logger.level=WARN, -Dtests.security.manager=true, -Dtests.seed=6B876C3C963351CB, -Dtests.task=:x-pack:plugin:watcher:internalClusterTest, --illegal-access=warn, -XX:+HeapDumpOnOutOfMemoryError, -esa, -XX:HeapDumpPath=/dev/shm/elastic+elasticsearch+master+multijob+fast+part2/x-pack/plugin/watcher/build/heapdump, -Xms512m, -Xmx512m, -Dfile.encoding=UTF-8, -Djava.io.tmpdir=/dev/shm/elastic+elasticsearch+master+multijob+fast+part2/x-pack/plugin/watcher/build/testrun/internalClusterTest/temp, -Duser.country=US, -Duser.language=en, -Duser.variant, -ea]
  1> [2020-11-17T00:23:05,097][WARN ][o.e.n.Node               ] [testVarsManual] version [8.0.0-SNAPSHOT] is a pre-release version of Elasticsearch and is not suitable for production
  1> [2020-11-17T00:23:05,097][INFO ][o.e.x.w.t.TimeWarpedWatcher] [testVarsManual] using time warped watchers plugin
  1> [2020-11-17T00:23:05,098][INFO ][o.e.p.PluginsService     ] [testVarsManual] no modules loaded
  1> [2020-11-17T00:23:05,099][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.analysis.common.CommonAnalysisPlugin]
  1> [2020-11-17T00:23:05,099][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.script.MockMustacheScriptEngine$TestPlugin]
  1> [2020-11-17T00:23:05,099][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.script.MockScriptService$TestPlugin]
  1> [2020-11-17T00:23:05,099][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.test.ESIntegTestCase$AssertActionNamePlugin]
  1> [2020-11-17T00:23:05,115][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.test.ESIntegTestCase$TestSeedPlugin]
  1> [2020-11-17T00:23:05,115][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.test.MockHttpTransport$TestPlugin]
  1> [2020-11-17T00:23:05,115][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.test.TestGeoShapeFieldMapperPlugin]
  1> [2020-11-17T00:23:05,116][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.test.store.MockFSIndexStore$TestPlugin]
  1> [2020-11-17T00:23:05,116][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.transport.nio.MockNioTransportPlugin]
  1> [2020-11-17T00:23:05,116][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.xpack.datastreams.DataStreamsPlugin]
  1> [2020-11-17T00:23:05,116][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.xpack.ilm.IndexLifecycle]
  1> [2020-11-17T00:23:05,116][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.xpack.watcher.test.TimeWarpedWatcher]
  1> [2020-11-17T00:23:05,117][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.xpack.watcher.test.integration.ExecutionVarsIntegrationTests$CustomScriptPlugin]
  1> [2020-11-17T00:23:05,122][INFO ][o.e.e.NodeEnvironment    ] [testVarsManual] using [1] data paths, mounts [[/dev/shm (tmpfs)]], net usable_space [44.1gb], net total_space [47.1gb], types [tmpfs]
  1> [2020-11-17T00:23:05,123][INFO ][o.e.e.NodeEnvironment    ] [testVarsManual] heap size [512mb], compressed ordinary object pointers [true]
  1> [2020-11-17T00:23:05,127][INFO ][o.e.n.Node               ] [testVarsManual] node name [node_s1], node ID [uq8lboudSfm6c8RBnNjhgw], cluster name [SUITE-TEST_WORKER_VM=[537]-CLUSTER_SEED=[-3581282154539098659]-HASH=[1309DA1142A]-cluster], roles [data, remote_cluster_client, ingest]
  1> [2020-11-17T00:23:05,355][INFO ][o.e.d.DiscoveryModule    ] [testVarsManual] using discovery type [zen] and seed hosts providers [settings, file]
  1> [2020-11-17T00:23:05,522][INFO ][o.e.n.Node               ] [testVarsManual] initialized
  1> [2020-11-17T00:23:05,526][INFO ][o.e.n.Node               ] [testVarsManual] version[8.0.0-SNAPSHOT], pid[139975], build[unknown/unknown/923b2b90c5d06ae1a1e26211a1ded65750d2ee58/2020-11-16T14:02:35.834120Z], OS[Linux/5.4.0-1028-gcp/amd64], JVM[Oracle Corporation/OpenJDK 64-Bit Server VM/11.0.2/11.0.2+7]
  1> [2020-11-17T00:23:05,526][INFO ][o.e.n.Node               ] [testVarsManual] JVM home [/var/lib/jenkins/.java/openjdk-11.0.2-linux]
  1> [2020-11-17T00:23:05,527][DEPRECATION][o.e.d.n.Node             ] [testVarsManual] data_stream.dataset="deprecation.elasticsearch" data_stream.namespace="default" data_stream.type="logs" ecs.version="1.6" key="no-jdk" message="no-jdk distributions that do not bundle a JDK are deprecated and will be removed in a future release"
  1> [2020-11-17T00:23:05,527][INFO ][o.e.n.Node               ] [testVarsManual] JVM arguments [-Dfile.encoding=UTF8, -Des.scripting.update.ctx_in_params=false, -Des.search.rewrite_sort=true, -Des.set.netty.runtime.available.processors=false, -Des.transport.cname_in_publish_address=true, -Dgradle.dist.lib=/var/lib/jenkins/.gradle/wrapper/dists/gradle-6.6.1-all/ejrtlte9hlw8v6ii20a9584rs/gradle-6.6.1/lib, -Dgradle.user.home=/var/lib/jenkins/.gradle, -Dgradle.worker.jar=/var/lib/jenkins/.gradle/caches/6.6.1/workerMain/gradle-worker.jar, -Dio.netty.noKeySetOptimization=true, -Dio.netty.noUnsafe=true, -Dio.netty.recycler.maxCapacityPerThread=0, -Djava.awt.headless=true, -Djava.locale.providers=SPI,COMPAT, -Djna.nosys=true, -Dorg.gradle.native=false, -Dtests.artifact=watcher, -Dtests.gradle=true, -Dtests.logger.level=WARN, -Dtests.security.manager=true, -Dtests.seed=6B876C3C963351CB, -Dtests.task=:x-pack:plugin:watcher:internalClusterTest, --illegal-access=warn, -XX:+HeapDumpOnOutOfMemoryError, -esa, -XX:HeapDumpPath=/dev/shm/elastic+elasticsearch+master+multijob+fast+part2/x-pack/plugin/watcher/build/heapdump, -Xms512m, -Xmx512m, -Dfile.encoding=UTF-8, -Djava.io.tmpdir=/dev/shm/elastic+elasticsearch+master+multijob+fast+part2/x-pack/plugin/watcher/build/testrun/internalClusterTest/temp, -Duser.country=US, -Duser.language=en, -Duser.variant, -ea]
  1> [2020-11-17T00:23:05,528][WARN ][o.e.n.Node               ] [testVarsManual] version [8.0.0-SNAPSHOT] is a pre-release version of Elasticsearch and is not suitable for production
  1> [2020-11-17T00:23:05,529][INFO ][o.e.x.w.t.TimeWarpedWatcher] [testVarsManual] using time warped watchers plugin
  1> [2020-11-17T00:23:05,530][INFO ][o.e.p.PluginsService     ] [testVarsManual] no modules loaded
  1> [2020-11-17T00:23:05,530][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.analysis.common.CommonAnalysisPlugin]
  1> [2020-11-17T00:23:05,530][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.script.MockMustacheScriptEngine$TestPlugin]
  1> [2020-11-17T00:23:05,531][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.script.MockScriptService$TestPlugin]
  1> [2020-11-17T00:23:05,532][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.test.ESIntegTestCase$AssertActionNamePlugin]
  1> [2020-11-17T00:23:05,547][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.test.ESIntegTestCase$TestSeedPlugin]
  1> [2020-11-17T00:23:05,547][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.test.MockHttpTransport$TestPlugin]
  1> [2020-11-17T00:23:05,547][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.test.TestGeoShapeFieldMapperPlugin]
  1> [2020-11-17T00:23:05,548][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.test.store.MockFSIndexStore$TestPlugin]
  1> [2020-11-17T00:23:05,548][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.transport.nio.MockNioTransportPlugin]
  1> [2020-11-17T00:23:05,548][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.xpack.datastreams.DataStreamsPlugin]
  1> [2020-11-17T00:23:05,548][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.xpack.ilm.IndexLifecycle]
  1> [2020-11-17T00:23:05,548][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.xpack.watcher.test.TimeWarpedWatcher]
  1> [2020-11-17T00:23:05,549][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.xpack.watcher.test.integration.ExecutionVarsIntegrationTests$CustomScriptPlugin]
  1> [2020-11-17T00:23:05,553][INFO ][o.e.e.NodeEnvironment    ] [testVarsManual] using [1] data paths, mounts [[/dev/shm (tmpfs)]], net usable_space [44.1gb], net total_space [47.1gb], types [tmpfs]
  1> [2020-11-17T00:23:05,553][INFO ][o.e.e.NodeEnvironment    ] [testVarsManual] heap size [512mb], compressed ordinary object pointers [true]
  1> [2020-11-17T00:23:05,556][INFO ][o.e.n.Node               ] [testVarsManual] node name [node_s2], node ID [TFVuCSeGRsOQw7e8SQ9uWQ], cluster name [SUITE-TEST_WORKER_VM=[537]-CLUSTER_SEED=[-3581282154539098659]-HASH=[1309DA1142A]-cluster], roles [data, remote_cluster_client, ingest]
  1> [2020-11-17T00:23:05,761][INFO ][o.e.d.DiscoveryModule    ] [testVarsManual] using discovery type [zen] and seed hosts providers [settings, file]
  1> [2020-11-17T00:23:05,855][INFO ][o.e.n.Node               ] [testVarsManual] initialized
  1> [2020-11-17T00:23:05,858][INFO ][o.e.n.Node               ] [testVarsManual] version[8.0.0-SNAPSHOT], pid[139975], build[unknown/unknown/923b2b90c5d06ae1a1e26211a1ded65750d2ee58/2020-11-16T14:02:35.834120Z], OS[Linux/5.4.0-1028-gcp/amd64], JVM[Oracle Corporation/OpenJDK 64-Bit Server VM/11.0.2/11.0.2+7]
  1> [2020-11-17T00:23:05,859][INFO ][o.e.n.Node               ] [testVarsManual] JVM home [/var/lib/jenkins/.java/openjdk-11.0.2-linux]
  1> [2020-11-17T00:23:05,860][DEPRECATION][o.e.d.n.Node             ] [testVarsManual] data_stream.dataset="deprecation.elasticsearch" data_stream.namespace="default" data_stream.type="logs" ecs.version="1.6" key="no-jdk" message="no-jdk distributions that do not bundle a JDK are deprecated and will be removed in a future release"
  1> [2020-11-17T00:23:05,861][INFO ][o.e.n.Node               ] [testVarsManual] JVM arguments [-Dfile.encoding=UTF8, -Des.scripting.update.ctx_in_params=false, -Des.search.rewrite_sort=true, -Des.set.netty.runtime.available.processors=false, -Des.transport.cname_in_publish_address=true, -Dgradle.dist.lib=/var/lib/jenkins/.gradle/wrapper/dists/gradle-6.6.1-all/ejrtlte9hlw8v6ii20a9584rs/gradle-6.6.1/lib, -Dgradle.user.home=/var/lib/jenkins/.gradle, -Dgradle.worker.jar=/var/lib/jenkins/.gradle/caches/6.6.1/workerMain/gradle-worker.jar, -Dio.netty.noKeySetOptimization=true, -Dio.netty.noUnsafe=true, -Dio.netty.recycler.maxCapacityPerThread=0, -Djava.awt.headless=true, -Djava.locale.providers=SPI,COMPAT, -Djna.nosys=true, -Dorg.gradle.native=false, -Dtests.artifact=watcher, -Dtests.gradle=true, -Dtests.logger.level=WARN, -Dtests.security.manager=true, -Dtests.seed=6B876C3C963351CB, -Dtests.task=:x-pack:plugin:watcher:internalClusterTest, --illegal-access=warn, -XX:+HeapDumpOnOutOfMemoryError, -esa, -XX:HeapDumpPath=/dev/shm/elastic+elasticsearch+master+multijob+fast+part2/x-pack/plugin/watcher/build/heapdump, -Xms512m, -Xmx512m, -Dfile.encoding=UTF-8, -Djava.io.tmpdir=/dev/shm/elastic+elasticsearch+master+multijob+fast+part2/x-pack/plugin/watcher/build/testrun/internalClusterTest/temp, -Duser.country=US, -Duser.language=en, -Duser.variant, -ea]
  1> [2020-11-17T00:23:05,862][WARN ][o.e.n.Node               ] [testVarsManual] version [8.0.0-SNAPSHOT] is a pre-release version of Elasticsearch and is not suitable for production
  1> [2020-11-17T00:23:05,863][INFO ][o.e.x.w.t.TimeWarpedWatcher] [testVarsManual] using time warped watchers plugin
  1> [2020-11-17T00:23:05,867][INFO ][o.e.p.PluginsService     ] [testVarsManual] no modules loaded
  1> [2020-11-17T00:23:05,869][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.analysis.common.CommonAnalysisPlugin]
  1> [2020-11-17T00:23:05,871][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.script.MockMustacheScriptEngine$TestPlugin]
  1> [2020-11-17T00:23:05,874][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.script.MockScriptService$TestPlugin]
  1> [2020-11-17T00:23:05,875][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.test.ESIntegTestCase$AssertActionNamePlugin]
  1> [2020-11-17T00:23:05,875][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.test.ESIntegTestCase$TestSeedPlugin]
  1> [2020-11-17T00:23:05,877][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.test.MockHttpTransport$TestPlugin]
  1> [2020-11-17T00:23:05,878][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.test.TestGeoShapeFieldMapperPlugin]
  1> [2020-11-17T00:23:05,878][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.test.store.MockFSIndexStore$TestPlugin]
  1> [2020-11-17T00:23:05,879][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.transport.nio.MockNioTransportPlugin]
  1> [2020-11-17T00:23:05,879][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.xpack.datastreams.DataStreamsPlugin]
  1> [2020-11-17T00:23:05,879][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.xpack.ilm.IndexLifecycle]
  1> [2020-11-17T00:23:05,879][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.xpack.watcher.test.TimeWarpedWatcher]
  1> [2020-11-17T00:23:05,879][INFO ][o.e.p.PluginsService     ] [testVarsManual] loaded plugin [org.elasticsearch.xpack.watcher.test.integration.ExecutionVarsIntegrationTests$CustomScriptPlugin]
  1> [2020-11-17T00:23:05,885][INFO ][o.e.e.NodeEnvironment    ] [testVarsManual] using [1] data paths, mounts [[/dev/shm (tmpfs)]], net usable_space [44.1gb], net total_space [47.1gb], types [tmpfs]
  1> [2020-11-17T00:23:05,886][INFO ][o.e.e.NodeEnvironment    ] [testVarsManual] heap size [512mb], compressed ordinary object pointers [true]
  1> [2020-11-17T00:23:05,892][INFO ][o.e.n.Node               ] [testVarsManual] node name [node_s3], node ID [YzpDD7oRRVK0GFwlx3-Vew], cluster name [SUITE-TEST_WORKER_VM=[537]-CLUSTER_SEED=[-3581282154539098659]-HASH=[1309DA1142A]-cluster], roles [data, remote_cluster_client, ingest]
  1> [2020-11-17T00:23:06,105][INFO ][o.e.d.DiscoveryModule    ] [testVarsManual] using discovery type [zen] and seed hosts providers [settings, file]
  1> [2020-11-17T00:23:06,241][INFO ][o.e.n.Node               ] [testVarsManual] initialized
  1> [2020-11-17T00:23:06,263][INFO ][o.e.n.Node               ] [[test_SUITE-TEST_WORKER_VM=[537]-CLUSTER_SEED=[-3581282154539098659]-HASH=[1309DA1142A]-cluster[T#1]]] starting ...
  1> [2020-11-17T00:23:06,284][INFO ][o.e.n.Node               ] [[test_SUITE-TEST_WORKER_VM=[537]-CLUSTER_SEED=[-3581282154539098659]-HASH=[1309DA1142A]-cluster[T#2]]] starting ...
  1> [2020-11-17T00:23:06,287][INFO ][o.e.n.Node               ] [[test_SUITE-TEST_WORKER_VM=[537]-CLUSTER_SEED=[-3581282154539098659]-HASH=[1309DA1142A]-cluster[T#3]]] starting ...
  1> [2020-11-17T00:23:06,295][INFO ][o.e.n.Node               ] [[test_SUITE-TEST_WORKER_VM=[537]-CLUSTER_SEED=[-3581282154539098659]-HASH=[1309DA1142A]-cluster[T#4]]] starting ...
  1> [2020-11-17T00:23:06,544][INFO ][o.e.t.TransportService   ] [[test_SUITE-TEST_WORKER_VM=[537]-CLUSTER_SEED=[-3581282154539098659]-HASH=[1309DA1142A]-cluster[T#4]]] publish_address {127.0.0.1:45269}, bound_addresses {[::1]:33831}, {127.0.0.1:45269}
  1> [2020-11-17T00:23:06,544][INFO ][o.e.t.TransportService   ] [[test_SUITE-TEST_WORKER_VM=[537]-CLUSTER_SEED=[-3581282154539098659]-HASH=[1309DA1142A]-cluster[T#3]]] publish_address {127.0.0.1:42469}, bound_addresses {[::1]:38223}, {127.0.0.1:42469}
  1> [2020-11-17T00:23:06,564][INFO ][o.e.t.TransportService   ] [[test_SUITE-TEST_WORKER_VM=[537]-CLUSTER_SEED=[-3581282154539098659]-HASH=[1309DA1142A]-cluster[T#1]]] publish_address {127.0.0.1:43047}, bound_addresses {[::1]:35243}, {127.0.0.1:43047}
  1> [2020-11-17T00:23:06,579][INFO ][o.e.t.TransportService   ] [[test_SUITE-TEST_WORKER_VM=[537]-CLUSTER_SEED=[-3581282154539098659]-HASH=[1309DA1142A]-cluster[T#2]]] publish_address {127.0.0.1:33507}, bound_addresses {[::1]:35527}, {127.0.0.1:33507}
  1> [2020-11-17T00:23:07,275][INFO ][o.e.c.c.Coordinator      ] [[test_SUITE-TEST_WORKER_VM=[537]-CLUSTER_SEED=[-3581282154539098659]-HASH=[1309DA1142A]-cluster[T#1]]] setting initial configuration to VotingConfiguration{7CguAlnHTV-nFWMuwaxa3Q}
  1> [2020-11-17T00:23:07,904][INFO ][o.e.c.s.MasterService    ] [node_s0] elected-as-master ([1] nodes joined)[{node_s0}{7CguAlnHTV-nFWMuwaxa3Q}{3QyrCFI_TQOCfE2dQ-8S9Q}{127.0.0.1}{127.0.0.1:43047}{imr}{xpack.installed=true} elect leader, _BECOME_MASTER_TASK_, _FINISH_ELECTION_], term: 1, version: 1, delta: master node changed {previous [], current [{node_s0}{7CguAlnHTV-nFWMuwaxa3Q}{3QyrCFI_TQOCfE2dQ-8S9Q}{127.0.0.1}{127.0.0.1:43047}{imr}{xpack.installed=true}]}
  1> [2020-11-17T00:23:08,059][INFO ][o.e.c.c.CoordinationState] [node_s0] cluster UUID set to [SV-hyV48R52ZoSB2BKMf0g]
  1> [2020-11-17T00:23:08,147][INFO ][o.e.c.s.ClusterApplierService] [node_s0] master node changed {previous [], current [{node_s0}{7CguAlnHTV-nFWMuwaxa3Q}{3QyrCFI_TQOCfE2dQ-8S9Q}{127.0.0.1}{127.0.0.1:43047}{imr}{xpack.installed=true}]}, term: 1, version: 1, reason: Publication{term=1, version=1}
  1> [2020-11-17T00:23:08,240][INFO ][o.e.n.Node               ] [[test_SUITE-TEST_WORKER_VM=[537]-CLUSTER_SEED=[-3581282154539098659]-HASH=[1309DA1142A]-cluster[T#1]]] started
  1> [2020-11-17T00:23:08,619][INFO ][o.e.g.GatewayService     ] [node_s0] recovered [0] indices into cluster_state
  1> [2020-11-17T00:23:08,624][INFO ][o.e.c.s.MasterService    ] [node_s0] node-join[{node_s3}{YzpDD7oRRVK0GFwlx3-Vew}{wWDGh_HhSRKOqAunMptCXA}{127.0.0.1}{127.0.0.1:45269}{dir}{xpack.installed=true} join existing leader, {node_s1}{uq8lboudSfm6c8RBnNjhgw}{7Lrpk5hDSQGGyzFxDur57g}{127.0.0.1}{127.0.0.1:33507}{dir}{xpack.installed=true} join existing leader, {node_s2}{TFVuCSeGRsOQw7e8SQ9uWQ}{ckoBbM5ERk6gJ8CerlIJEA}{127.0.0.1}{127.0.0.1:42469}{dir}{xpack.installed=true} join existing leader], term: 1, version: 3, delta: added {{node_s2}{TFVuCSeGRsOQw7e8SQ9uWQ}{ckoBbM5ERk6gJ8CerlIJEA}{127.0.0.1}{127.0.0.1:42469}{dir}{xpack.installed=true},{node_s1}{uq8lboudSfm6c8RBnNjhgw}{7Lrpk5hDSQGGyzFxDur57g}{127.0.0.1}{127.0.0.1:33507}{dir}{xpack.installed=true},{node_s3}{YzpDD7oRRVK0GFwlx3-Vew}{wWDGh_HhSRKOqAunMptCXA}{127.0.0.1}{127.0.0.1:45269}{dir}{xpack.installed=true}}
  1> [2020-11-17T00:23:08,761][INFO ][o.e.c.s.ClusterApplierService] [node_s1] master node changed {previous [], current [{node_s0}{7CguAlnHTV-nFWMuwaxa3Q}{3QyrCFI_TQOCfE2dQ-8S9Q}{127.0.0.1}{127.0.0.1:43047}{imr}{xpack.installed=true}]}, added {{node_s0}{7CguAlnHTV-nFWMuwaxa3Q}{3QyrCFI_TQOCfE2dQ-8S9Q}{127.0.0.1}{127.0.0.1:43047}{imr}{xpack.installed=true},{node_s2}{TFVuCSeGRsOQw7e8SQ9uWQ}{ckoBbM5ERk6gJ8CerlIJEA}{127.0.0.1}{127.0.0.1:42469}{dir}{xpack.installed=true},{node_s3}{YzpDD7oRRVK0GFwlx3-Vew}{wWDGh_HhSRKOqAunMptCXA}{127.0.0.1}{127.0.0.1:45269}{dir}{xpack.installed=true}}, term: 1, version: 3, reason: ApplyCommitRequest{term=1, version=3, sourceNode={node_s0}{7CguAlnHTV-nFWMuwaxa3Q}{3QyrCFI_TQOCfE2dQ-8S9Q}{127.0.0.1}{127.0.0.1:43047}{imr}{xpack.installed=true}}
  1> [2020-11-17T00:23:08,762][INFO ][o.e.c.s.ClusterApplierService] [node_s2] master node changed {previous [], current [{node_s0}{7CguAlnHTV-nFWMuwaxa3Q}{3QyrCFI_TQOCfE2dQ-8S9Q}{127.0.0.1}{127.0.0.1:43047}{imr}{xpack.installed=true}]}, added {{node_s0}{7CguAlnHTV-nFWMuwaxa3Q}{3QyrCFI_TQOCfE2dQ-8S9Q}{127.0.0.1}{127.0.0.1:43047}{imr}{xpack.installed=true},{node_s1}{uq8lboudSfm6c8RBnNjhgw}{7Lrpk5hDSQGGyzFxDur57g}{127.0.0.1}{127.0.0.1:33507}{dir}{xpack.installed=true},{node_s3}{YzpDD7oRRVK0GFwlx3-Vew}{wWDGh_HhSRKOqAunMptCXA}{127.0.0.1}{127.0.0.1:45269}{dir}{xpack.installed=true}}, term: 1, version: 3, reason: ApplyCommitRequest{term=1, version=3, sourceNode={node_s0}{7CguAlnHTV-nFWMuwaxa3Q}{3QyrCFI_TQOCfE2dQ-8S9Q}{127.0.0.1}{127.0.0.1:43047}{imr}{xpack.installed=true}}
  1> [2020-11-17T00:23:08,767][INFO ][o.e.c.s.ClusterApplierService] [node_s3] master node changed {previous [], current [{node_s0}{7CguAlnHTV-nFWMuwaxa3Q}{3QyrCFI_TQOCfE2dQ-8S9Q}{127.0.0.1}{127.0.0.1:43047}{imr}{xpack.installed=true}]}, added {{node_s0}{7CguAlnHTV-nFWMuwaxa3Q}{3QyrCFI_TQOCfE2dQ-8S9Q}{127.0.0.1}{127.0.0.1:43047}{imr}{xpack.installed=true},{node_s2}{TFVuCSeGRsOQw7e8SQ9uWQ}{ckoBbM5ERk6gJ8CerlIJEA}{127.0.0.1}{127.0.0.1:42469}{dir}{xpack.installed=true},{node_s1}{uq8lboudSfm6c8RBnNjhgw}{7Lrpk5hDSQGGyzFxDur57g}{127.0.0.1}{127.0.0.1:33507}{dir}{xpack.installed=true}}, term: 1, version: 3, reason: ApplyCommitRequest{term=1, version=3, sourceNode={node_s0}{7CguAlnHTV-nFWMuwaxa3Q}{3QyrCFI_TQOCfE2dQ-8S9Q}{127.0.0.1}{127.0.0.1:43047}{imr}{xpack.installed=true}}
  1> [2020-11-17T00:23:08,840][INFO ][o.e.n.Node               ] [[test_SUITE-TEST_WORKER_VM=[537]-CLUSTER_SEED=[-3581282154539098659]-HASH=[1309DA1142A]-cluster[T#3]]] started
  1> [2020-11-17T00:23:08,841][INFO ][o.e.n.Node               ] [[test_SUITE-TEST_WORKER_VM=[537]-CLUSTER_SEED=[-3581282154539098659]-HASH=[1309DA1142A]-cluster[T#2]]] started
  1> [2020-11-17T00:23:08,842][INFO ][o.e.n.Node               ] [[test_SUITE-TEST_WORKER_VM=[537]-CLUSTER_SEED=[-3581282154539098659]-HASH=[1309DA1142A]-cluster[T#4]]] started
  1> [2020-11-17T00:23:08,848][INFO ][o.e.c.s.ClusterApplierService] [node_s0] added {{node_s2}{TFVuCSeGRsOQw7e8SQ9uWQ}{ckoBbM5ERk6gJ8CerlIJEA}{127.0.0.1}{127.0.0.1:42469}{dir}{xpack.installed=true},{node_s1}{uq8lboudSfm6c8RBnNjhgw}{7Lrpk5hDSQGGyzFxDur57g}{127.0.0.1}{127.0.0.1:33507}{dir}{xpack.installed=true},{node_s3}{YzpDD7oRRVK0GFwlx3-Vew}{wWDGh_HhSRKOqAunMptCXA}{127.0.0.1}{127.0.0.1:45269}{dir}{xpack.installed=true}}, term: 1, version: 3, reason: Publication{term=1, version=3}
  1> [2020-11-17T00:23:09,867][INFO ][o.e.c.m.MetadataIndexTemplateService] [node_s0] adding index template [.triggered_watches] for index patterns [.triggered_watches*]
  1> [2020-11-17T00:23:10,194][INFO ][o.e.c.m.MetadataIndexTemplateService] [node_s0] adding index template [.watch-history-14] for index patterns [.watcher-history-14*]
  1> [2020-11-17T00:23:10,381][INFO ][o.e.c.m.MetadataIndexTemplateService] [node_s0] adding index template [.watches] for index patterns [.watches*]
  1> [2020-11-17T00:23:10,584][INFO ][o.e.c.m.MetadataIndexTemplateService] [node_s0] adding index template [.slm-history] for index patterns [.slm-history-5*]
  1> [2020-11-17T00:23:10,677][INFO ][o.e.x.i.a.TransportPutLifecycleAction] [node_s0] adding index lifecycle policy [watch-history-ilm-policy]
  1> [2020-11-17T00:23:10,854][INFO ][o.e.x.i.a.TransportPutLifecycleAction] [node_s0] adding index lifecycle policy [slm-history-ilm-policy]
  1> [2020-11-17T00:23:11,461][INFO ][o.e.l.LicenseService     ] [node_s1] license [79a94ba5-7aa0-485f-bcfb-2d91ba528a2c] mode [trial] - valid
  1> [2020-11-17T00:23:11,503][INFO ][o.e.l.LicenseService     ] [node_s2] license [79a94ba5-7aa0-485f-bcfb-2d91ba528a2c] mode [trial] - valid
  1> [2020-11-17T00:23:11,543][INFO ][o.e.l.LicenseService     ] [node_s3] license [79a94ba5-7aa0-485f-bcfb-2d91ba528a2c] mode [trial] - valid
  1> [2020-11-17T00:23:11,680][INFO ][o.e.l.LicenseService     ] [node_s0] license [79a94ba5-7aa0-485f-bcfb-2d91ba528a2c] mode [trial] - valid
  1> [2020-11-17T00:23:11,733][WARN ][o.e.c.m.MetadataIndexTemplateService] [node_s0] legacy template [random_index_template] has index patterns [*] matching patterns from existing composable templates [.triggered_watches,.watch-history-14,.slm-history,.watches] with patterns (.triggered_watches => [.triggered_watches*],.watch-history-14 => [.watcher-history-14*],.slm-history => [.slm-history-5*],.watches => [.watches*]); this template [random_index_template] may be ignored in favor of a composable template at index creation time
  1> [2020-11-17T00:23:11,734][INFO ][o.e.c.m.MetadataIndexTemplateService] [node_s0] adding template [random_index_template] for index patterns [*]
  1> [2020-11-17T00:23:11,814][INFO ][o.e.x.w.t.i.ExecutionVarsIntegrationTests] [testVarsManual] [ExecutionVarsIntegrationTests#testVarsManual]: all set up test
  1> [2020-11-17T00:23:11,826][INFO ][o.e.x.w.t.i.ExecutionVarsIntegrationTests] [testVarsManual] [ExecutionVarsIntegrationTests#testVarsManual]: freezing time on nodes
  1> [2020-11-17T00:23:11,849][INFO ][o.e.x.w.t.i.ExecutionVarsIntegrationTests] [testVarsManual] waiting to stop watcher, current states [Tuple [v1=node_s0 (0), v2=STARTED], Tuple [v1=node_s2 (0), v2=STARTED], Tuple [v1=node_s1 (0), v2=STARTED], Tuple [v1=node_s3 (0), v2=STARTED]]
  1> [2020-11-17T00:23:11,941][INFO ][o.e.x.w.WatcherService   ] [node_s2] stopping watch service, reason [watcher manually marked to shutdown by cluster state update]
  1> [2020-11-17T00:23:11,942][INFO ][o.e.x.w.WatcherService   ] [node_s3] stopping watch service, reason [watcher manually marked to shutdown by cluster state update]
  1> [2020-11-17T00:23:11,943][INFO ][o.e.x.w.WatcherService   ] [node_s1] stopping watch service, reason [watcher manually marked to shutdown by cluster state update]
  1> [2020-11-17T00:23:11,943][INFO ][o.e.x.w.WatcherLifeCycleService] [node_s3] watcher has stopped
  1> [2020-11-17T00:23:11,944][INFO ][o.e.x.w.WatcherLifeCycleService] [node_s1] watcher has stopped
  1> [2020-11-17T00:23:11,943][INFO ][o.e.x.w.WatcherLifeCycleService] [node_s2] watcher has stopped
  1> [2020-11-17T00:23:11,955][INFO ][o.e.x.w.WatcherService   ] [node_s0] stopping watch service, reason [watcher manually marked to shutdown by cluster state update]
  1> [2020-11-17T00:23:11,956][INFO ][o.e.x.w.WatcherLifeCycleService] [node_s0] watcher has stopped
  1> [2020-11-17T00:23:11,973][INFO ][o.e.x.w.t.i.ExecutionVarsIntegrationTests] [testVarsManual] waiting to stop watcher, current states [Tuple [v1=node_s0 (0), v2=STOPPED], Tuple [v1=node_s2 (0), v2=STOPPED], Tuple [v1=node_s1 (0), v2=STOPPED], Tuple [v1=node_s3 (0), v2=STOPPED]]
  1> [2020-11-17T00:23:11,989][DEPRECATION][o.e.d.c.m.MetadataCreateIndexService] [node_s0] data_stream.dataset="deprecation.elasticsearch" data_stream.namespace="default" data_stream.type="logs" ecs.version="1.6" key="index_name_starts_with_dot" message="index name [.watchesptbvw] starts with a dot '.', in the next major version, index names starting with a dot are reserved for hidden indices and system indices"
  1> [2020-11-17T00:23:12,050][INFO ][o.e.c.m.MetadataCreateIndexService] [node_s0] [.watchesptbvw] creating index, cause [Index to test aliases with .watches index], templates [.watches], shards [1]/[0]
  1> [2020-11-17T00:23:12,084][INFO ][o.e.c.r.a.AllocationService] [node_s0] updating number_of_replicas to [1] for indices [.watchesptbvw]
  1> [2020-11-17T00:23:13,131][INFO ][o.e.c.m.MetadataCreateIndexService] [node_s0] [rxetwnwf] creating index, cause [api], templates [random_index_template], shards [1]/[1]
  1> [2020-11-17T00:23:13,920][INFO ][o.e.c.r.a.AllocationService] [node_s0] current.health="GREEN" message="Cluster health status changed from [YELLOW] to [GREEN] (reason: [shards started [[.watchesptbvw][0]]])." previous.health="YELLOW" reason="shards started [[.watchesptbvw][0]]"
  1> [2020-11-17T00:23:13,995][INFO ][o.e.c.m.MetadataDeleteIndexService] [node_s0] [.watchesptbvw/KTSqLxaySz-s176I_FEHxw] deleting index
  1> [2020-11-17T00:23:14,290][INFO ][o.e.x.w.t.i.ExecutionVarsIntegrationTests] [testVarsManual] set alias for .watches index to [rxetwnwf]
  1> [2020-11-17T00:23:14,319][DEPRECATION][o.e.d.c.m.MetadataCreateIndexService] [node_s0] data_stream.dataset="deprecation.elasticsearch" data_stream.namespace="default" data_stream.type="logs" ecs.version="1.6" key="index_name_starts_with_dot" message="index name [.triggered_watches-alias-index] starts with a dot '.', in the next major version, index names starting with a dot are reserved for hidden indices and system indices"
  1> [2020-11-17T00:23:14,334][INFO ][o.e.c.m.MetadataCreateIndexService] [node_s0] [.triggered_watches-alias-index] creating index, cause [Index to test aliases with .triggered-watches index], templates [.triggered_watches], shards [1]/[1]
  1> [2020-11-17T00:23:14,593][INFO ][o.e.c.m.MetadataCreateIndexService] [node_s0] [szxqkci] creating index, cause [api], templates [random_index_template], shards [1]/[1]
  1> [2020-11-17T00:23:15,262][INFO ][o.e.c.r.a.AllocationService] [node_s0] current.health="GREEN" message="Cluster health status changed from [YELLOW] to [GREEN] (reason: [shards started [[szxqkci][0]]])." previous.health="YELLOW" reason="shards started [[szxqkci][0]]"
  1> [2020-11-17T00:23:15,325][INFO ][o.e.c.m.MetadataDeleteIndexService] [node_s0] [.triggered_watches-alias-index/v5ZC0qjRTQuQmSABOtSOXQ] deleting index
  1> [2020-11-17T00:23:15,586][INFO ][o.e.x.w.t.i.ExecutionVarsIntegrationTests] [testVarsManual] set alias for .triggered-watches index to [szxqkci]
  1> [2020-11-17T00:23:15,591][INFO ][o.e.x.w.t.i.ExecutionVarsIntegrationTests] [testVarsManual] waiting to start watcher, current states [Tuple [v1=node_s0, v2=STOPPED], Tuple [v1=node_s2, v2=STOPPED], Tuple [v1=node_s1, v2=STOPPED], Tuple [v1=node_s3, v2=STOPPED]]
  1> [2020-11-17T00:23:15,705][INFO ][o.e.x.w.t.i.ExecutionVarsIntegrationTests] [testVarsManual] waiting to start watcher, current states [Tuple [v1=node_s0, v2=STARTING], Tuple [v1=node_s2, v2=STARTING], Tuple [v1=node_s1, v2=STARTED], Tuple [v1=node_s3, v2=STARTING]]
  1> [2020-11-17T00:23:15,711][INFO ][o.e.x.w.t.i.ExecutionVarsIntegrationTests] [testVarsManual] waiting to start watcher, current states [Tuple [v1=node_s0, v2=STARTING], Tuple [v1=node_s2, v2=STARTING], Tuple [v1=node_s1, v2=STARTED], Tuple [v1=node_s3, v2=STARTING]]
  1> [2020-11-17T00:23:15,718][INFO ][o.e.x.w.t.i.ExecutionVarsIntegrationTests] [testVarsManual] waiting to start watcher, current states [Tuple [v1=node_s0, v2=STARTING], Tuple [v1=node_s2, v2=STARTING], Tuple [v1=node_s1, v2=STARTED], Tuple [v1=node_s3, v2=STARTING]]
  1> [2020-11-17T00:23:15,733][INFO ][o.e.x.w.t.i.ExecutionVarsIntegrationTests] [testVarsManual] waiting to start watcher, current states [Tuple [v1=node_s0, v2=STARTED], Tuple [v1=node_s2, v2=STARTING], Tuple [v1=node_s1, v2=STARTED], Tuple [v1=node_s3, v2=STARTING]]
  1> [2020-11-17T00:23:15,756][INFO ][o.e.x.w.t.i.ExecutionVarsIntegrationTests] [testVarsManual] waiting to start watcher, current states [Tuple [v1=node_s0, v2=STARTED], Tuple [v1=node_s2, v2=STARTING], Tuple [v1=node_s1, v2=STARTED], Tuple [v1=node_s3, v2=STARTING]]
  1> [2020-11-17T00:23:15,797][INFO ][o.e.x.w.t.i.ExecutionVarsIntegrationTests] [testVarsManual] waiting to start watcher, current states [Tuple [v1=node_s0, v2=STARTED], Tuple [v1=node_s2, v2=STARTING], Tuple [v1=node_s1, v2=STARTED], Tuple [v1=node_s3, v2=STARTING]]
  1> [2020-11-17T00:23:15,888][INFO ][o.e.x.w.t.i.ExecutionVarsIntegrationTests] [testVarsManual] waiting to start watcher, current states [Tuple [v1=node_s0, v2=STARTED], Tuple [v1=node_s2, v2=STARTING], Tuple [v1=node_s1, v2=STARTED], Tuple [v1=node_s3, v2=STARTING]]
  1> [2020-11-17T00:23:16,020][INFO ][o.e.x.w.t.i.ExecutionVarsIntegrationTests] [testVarsManual] waiting to start watcher, current states [Tuple [v1=node_s0, v2=STARTED], Tuple [v1=node_s2, v2=STARTED], Tuple [v1=node_s1, v2=STARTED], Tuple [v1=node_s3, v2=STARTED]]
  1> [2020-11-17T00:23:16,441][INFO ][o.e.x.w.a.l.ExecutableLoggingAction] [node_s3] _text
  1> [2020-11-17T00:23:16,445][INFO ][o.e.x.w.a.l.ExecutableLoggingAction] [node_s3] _text
  1> [2020-11-17T00:23:16,520][INFO ][o.e.x.w.t.i.ExecutionVarsIntegrationTests] [testVarsManual] [#testVarsManual]: clearing watcher state
  1> [2020-11-17T00:23:16,522][INFO ][o.e.x.w.t.i.ExecutionVarsIntegrationTests] [testVarsManual] waiting to stop watcher, current states [Tuple [v1=node_s0 (0), v2=STARTED], Tuple [v1=node_s2 (0), v2=STARTED], Tuple [v1=node_s1 (0), v2=STARTED], Tuple [v1=node_s3 (0), v2=STARTED]]
  1> [2020-11-17T00:23:16,564][INFO ][o.e.x.w.WatcherService   ] [node_s1] stopping watch service, reason [watcher manually marked to shutdown by cluster state update]
  1> [2020-11-17T00:23:16,564][INFO ][o.e.x.w.WatcherService   ] [node_s2] stopping watch service, reason [watcher manually marked to shutdown by cluster state update]
  1> [2020-11-17T00:23:16,564][INFO ][o.e.x.w.WatcherService   ] [node_s3] stopping watch service, reason [watcher manually marked to shutdown by cluster state update]
  1> [2020-11-17T00:23:16,564][INFO ][o.e.x.w.WatcherLifeCycleService] [node_s1] watcher has stopped
  1> [2020-11-17T00:23:16,565][INFO ][o.e.x.w.WatcherLifeCycleService] [node_s2] watcher has stopped
  1> [2020-11-17T00:23:16,570][INFO ][o.e.x.w.WatcherLifeCycleService] [node_s3] watcher has stopped
  1> [2020-11-17T00:23:16,579][INFO ][o.e.x.w.WatcherService   ] [node_s0] stopping watch service, reason [watcher manually marked to shutdown by cluster state update]
  1> [2020-11-17T00:23:16,580][INFO ][o.e.x.w.WatcherLifeCycleService] [node_s0] watcher has stopped
  1> [2020-11-17T00:23:16,608][INFO ][o.e.x.w.t.i.ExecutionVarsIntegrationTests] [testVarsManual] waiting to stop watcher, current states [Tuple [v1=node_s0 (0), v2=STOPPED], Tuple [v1=node_s2 (0), v2=STOPPED], Tuple [v1=node_s1 (0), v2=STOPPED], Tuple [v1=node_s3 (0), v2=STOPPED]]
  1> [2020-11-17T00:23:16,647][INFO ][o.e.x.w.t.i.ExecutionVarsIntegrationTests] [testVarsManual] [ExecutionVarsIntegrationTests#testVarsManual]: cleaning up after test
  1> [2020-11-17T00:23:16,647][INFO ][o.e.t.InternalTestCluster] [testVarsManual] Clearing active scheme time frozen, expected healing time 0s
  1> [2020-11-17T00:23:16,962][INFO ][o.e.c.m.MetadataDeleteIndexService] [node_s0] [rxetwnwf/AmuHMtYlTG2o-_zPzNZFSQ] deleting index
  1> [2020-11-17T00:23:16,962][INFO ][o.e.c.m.MetadataDeleteIndexService] [node_s0] [szxqkci/jpg3xWe3TeqIazb__3D4jQ] deleting index
  1> [2020-11-17T00:23:17,086][INFO ][o.e.c.m.MetadataIndexTemplateService] [node_s0] removing template [random_index_template]
  1> [2020-11-17T00:23:17,167][INFO ][o.e.x.w.t.i.ExecutionVarsIntegrationTests] [testVarsManual] [ExecutionVarsIntegrationTests#testVarsManual]: cleaned up after test
  1> [2020-11-17T00:23:17,170][INFO ][o.e.x.w.t.i.ExecutionVarsIntegrationTests] [testVarsManual] after test
  1> [2020-11-17T00:23:17,262][INFO ][o.e.x.w.t.i.ExecutionVarsIntegrationTests] [testVars] before test
  1> [2020-11-17T00:23:17,267][INFO ][o.e.x.w.t.i.ExecutionVarsIntegrationTests] [testVars] [ExecutionVarsIntegrationTests#testVars]: setting up test
  1> [2020-11-17T00:23:17,290][WARN ][o.e.c.m.MetadataIndexTemplateService] [node_s0] legacy template [random_index_template] has index patterns [*] matching patterns from existing composable templates [.triggered_watches,.watch-history-14,.slm-history,.watches] with patterns (.triggered_watches => [.triggered_watches*],.watch-history-14 => [.watcher-history-14*],.slm-history => [.slm-history-5*],.watches => [.watches*]); this template [random_index_template] may be ignored in favor of a composable template at index creation time
  1> [2020-11-17T00:23:17,291][INFO ][o.e.c.m.MetadataIndexTemplateService] [node_s0] adding template [random_index_template] for index patterns [*]
  1> [2020-11-17T00:23:17,344][INFO ][o.e.x.w.t.i.ExecutionVarsIntegrationTests] [testVars] [ExecutionVarsIntegrationTests#testVars]: all set up test
  1> [2020-11-17T00:23:17,348][INFO ][o.e.x.w.t.i.ExecutionVarsIntegrationTests] [testVars] [ExecutionVarsIntegrationTests#testVars]: freezing time on nodes
  1> [2020-11-17T00:23:17,353][INFO ][o.e.x.w.t.i.ExecutionVarsIntegrationTests] [testVars] waiting to stop watcher, current states [Tuple [v1=node_s0 (0), v2=STOPPED], Tuple [v1=node_s2 (0), v2=STOPPED], Tuple [v1=node_s1 (0), v2=STOPPED], Tuple [v1=node_s3 (0), v2=STOPPED]]
  1> [2020-11-17T00:23:17,357][DEPRECATION][o.e.d.c.m.MetadataCreateIndexService] [node_s0] data_stream.dataset="deprecation.elasticsearch" data_stream.namespace="default" data_stream.type="logs" ecs.version="1.6" key="index_name_starts_with_dot" message="index name [.watches] starts with a dot '.', in the next major version, index names starting with a dot are reserved for hidden indices and system indices"
  1> [2020-11-17T00:23:17,365][INFO ][o.e.c.m.MetadataCreateIndexService] [node_s0] [.watches] creating index, cause [api], templates [.watches], shards [1]/[0]
  1> [2020-11-17T00:23:17,374][INFO ][o.e.c.r.a.AllocationService] [node_s0] updating number_of_replicas to [1] for indices [.watches]
  1> [2020-11-17T00:23:17,662][DEPRECATION][o.e.d.c.m.MetadataCreateIndexService] [node_s0] data_stream.dataset="deprecation.elasticsearch" data_stream.namespace="default" data_stream.type="logs" ecs.version="1.6" key="index_name_starts_with_dot" message="index name [.triggered_watches] starts with a dot '.', in the next major version, index names starting with a dot are reserved for hidden indices and system indices"
  1> [2020-11-17T00:23:17,673][INFO ][o.e.c.m.MetadataCreateIndexService] [node_s0] [.triggered_watches] creating index, cause [api], templates [.triggered_watches], shards [1]/[1]
  1> [2020-11-17T00:23:18,054][INFO ][o.e.x.w.t.i.ExecutionVarsIntegrationTests] [testVars] waiting to start watcher, current states [Tuple [v1=node_s0, v2=STOPPED], Tuple [v1=node_s2, v2=STOPPED], Tuple [v1=node_s1, v2=STOPPED], Tuple [v1=node_s3, v2=STOPPED]]
  1> [2020-11-17T00:23:18,171][INFO ][o.e.x.w.t.i.ExecutionVarsIntegrationTests] [testVars] waiting to start watcher, current states [Tuple [v1=node_s0, v2=STARTED], Tuple [v1=node_s2, v2=STARTING], Tuple [v1=node_s1, v2=STARTED], Tuple [v1=node_s3, v2=STARTED]]
  1> [2020-11-17T00:23:18,207][INFO ][o.e.x.w.t.i.ExecutionVarsIntegrationTests] [testVars] waiting to start watcher, current states [Tuple [v1=node_s0, v2=STARTED], Tuple [v1=node_s2, v2=STARTING], Tuple [v1=node_s1, v2=STARTED], Tuple [v1=node_s3, v2=STARTED]]
  1> [2020-11-17T00:23:18,213][INFO ][o.e.x.w.t.i.ExecutionVarsIntegrationTests] [testVars] waiting to start watcher, current states [Tuple [v1=node_s0, v2=STARTED], Tuple [v1=node_s2, v2=STARTING], Tuple [v1=node_s1, v2=STARTED], Tuple [v1=node_s3, v2=STARTED]]
  1> [2020-11-17T00:23:18,224][INFO ][o.e.x.w.t.i.ExecutionVarsIntegrationTests] [testVars] waiting to start watcher, current states [Tuple [v1=node_s0, v2=STARTED], Tuple [v1=node_s2, v2=STARTING], Tuple [v1=node_s1, v2=STARTED], Tuple [v1=node_s3, v2=STARTED]]
  1> [2020-11-17T00:23:18,234][INFO ][o.e.x.w.WatcherService   ] [node_s1] reloading watcher, reason [new local watcher shard allocation ids], cancelled [0] queued tasks
  1> [2020-11-17T00:23:18,242][INFO ][o.e.x.w.t.i.ExecutionVarsIntegrationTests] [testVars] waiting to start watcher, current states [Tuple [v1=node_s0, v2=STARTED], Tuple [v1=node_s2, v2=STARTING], Tuple [v1=node_s1, v2=STARTED], Tuple [v1=node_s3, v2=STARTED]]
  1> [2020-11-17T00:23:18,278][INFO ][o.e.x.w.t.i.ExecutionVarsIntegrationTests] [testVars] waiting to start watcher, current states [Tuple [v1=node_s0, v2=STARTED], Tuple [v1=node_s2, v2=STARTED], Tuple [v1=node_s1, v2=STARTED], Tuple [v1=node_s3, v2=STARTED]]
  1> [2020-11-17T00:23:18,513][INFO ][o.e.x.w.t.ScheduleTriggerEngineMock] [testVars] not executing watch [sxrSlLiftaevxzFKiooF] on this scheduler because it is paused
  1> [2020-11-17T00:23:18,516][INFO ][o.e.x.w.t.i.ExecutionVarsIntegrationTests] [testVars] [#testVars]: clearing watcher state
  1> [2020-11-17T00:23:18,521][INFO ][o.e.x.w.t.i.ExecutionVarsIntegrationTests] [testVars] waiting to stop watcher, current states [Tuple [v1=node_s0 (0), v2=STARTED], Tuple [v1=node_s2 (0), v2=STARTED], Tuple [v1=node_s1 (0), v2=STARTED], Tuple [v1=node_s3 (0), v2=STARTED]]
  1> [2020-11-17T00:23:18,578][INFO ][o.e.x.w.WatcherService   ] [node_s3] stopping watch service, reason [watcher manually marked to shutdown by cluster state update]
  1> [2020-11-17T00:23:18,578][INFO ][o.e.x.w.WatcherService   ] [node_s2] stopping watch service, reason [watcher manually marked to shutdown by cluster state update]
  1> [2020-11-17T00:23:18,579][INFO ][o.e.x.w.WatcherService   ] [node_s1] stopping watch service, reason [watcher manually marked to shutdown by cluster state update]
  1> [2020-11-17T00:23:18,579][INFO ][o.e.x.w.WatcherLifeCycleService] [node_s3] watcher has stopped
  1> [2020-11-17T00:23:18,579][INFO ][o.e.x.w.WatcherLifeCycleService] [node_s1] watcher has stopped
  1> [2020-11-17T00:23:18,581][INFO ][o.e.x.w.WatcherLifeCycleService] [node_s2] watcher has stopped
  1> [2020-11-17T00:23:18,586][INFO ][o.e.x.w.WatcherService   ] [node_s0] stopping watch service, reason [watcher manually marked to shutdown by cluster state update]
  1> [2020-11-17T00:23:18,587][INFO ][o.e.x.w.WatcherLifeCycleService] [node_s0] watcher has stopped
  1> [2020-11-17T00:23:18,595][INFO ][o.e.x.w.t.i.ExecutionVarsIntegrationTests] [testVars] waiting to stop watcher, current states [Tuple [v1=node_s0 (0), v2=STOPPED], Tuple [v1=node_s2 (0), v2=STOPPED], Tuple [v1=node_s1 (0), v2=STOPPED], Tuple [v1=node_s3 (0), v2=STOPPED]]
  1> [2020-11-17T00:23:18,596][INFO ][o.e.x.w.t.i.ExecutionVarsIntegrationTests] [testVars] [ExecutionVarsIntegrationTests#testVars]: cleaning up after test
  1> [2020-11-17T00:23:18,597][INFO ][o.e.t.InternalTestCluster] [testVars] Clearing active scheme time frozen, expected healing time 0s
  1> [2020-11-17T00:23:18,727][INFO ][o.e.c.r.a.AllocationService] [node_s0] current.health="GREEN" message="Cluster health status changed from [YELLOW] to [GREEN] (reason: [shards started [[.triggered_watches][0]]])." previous.health="YELLOW" reason="shards started [[.triggered_watches][0]]"
  1> [2020-11-17T00:23:18,895][INFO ][o.e.c.m.MetadataDeleteIndexService] [node_s0] [.triggered_watches/BN3IQb9HQ827vDtn7_JlEg] deleting index
  1> [2020-11-17T00:23:18,895][INFO ][o.e.c.m.MetadataDeleteIndexService] [node_s0] [.watches/rsrtJEuAQmqQ9t8XwUw_Xg] deleting index
  1> [2020-11-17T00:23:19,070][INFO ][o.e.c.m.MetadataIndexTemplateService] [node_s0] removing template [random_index_template]
  1> [2020-11-17T00:23:19,110][INFO ][o.e.x.w.t.i.ExecutionVarsIntegrationTests] [testVars] [ExecutionVarsIntegrationTests#testVars]: cleaned up after test
  1> [2020-11-17T00:23:19,112][INFO ][o.e.x.w.t.i.ExecutionVarsIntegrationTests] [testVars] after test
  2> REPRODUCE WITH: ./gradlew ':x-pack:plugin:watcher:internalClusterTest' --tests "org.elasticsearch.xpack.watcher.test.integration.ExecutionVarsIntegrationTests.testVars" -Dtests.seed=6B876C3C963351CB -Dtests.security.manager=true -Dtests.locale=ar-AE
@valeriy42 valeriy42 added >test-failure Triaged test failures from CI :Data Management/Watcher labels Nov 16, 2020
@elasticmachine elasticmachine added the Team:Data Management Meta label for data/management team label Nov 16, 2020
@elasticmachine
Copy link
Collaborator

Pinging @elastic/es-core-features (Team:Core/Features)

@valeriy42 valeriy42 mentioned this issue Nov 16, 2020
Merged
valeriy42 added a commit that referenced this issue Nov 16, 2020
@valeriy42
[TEST] Mute ExecutionVarsIntegrationTests.testVars (#65088)
eb7de50 
Relates #65086
@probakowski probakowski mentioned this issue Nov 18, 2020
Merged
probakowski added a commit that referenced this issue Nov 18, 2020
@probakowski
Fix trigger assertion error in watcher tests (#65186)
b3a4fc4 
When we trigger watcher in tests we may fail if scheduler is paused.
That can happen when watcher is reloading due to changes in its shards. This is transient state and retry should fix it.
This change adds assertBusy around triggering code so we will try again.

Closes #65183 #65176 #65117 #65091 #65089 #65086 #65064 #65063
@probakowski
Copy link
Contributor

Should be fixed by #65186

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
:Data Management/Watcher Team:Data Management Meta label for data/management team >test-failure Triaged test failures from CI
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@valeriy42 @probakowski @elasticmachine