[CI] SmokeTestWatcherWithSecurityIT.* failing

[elasticmachine]

Original comment by @ywelsch:

The tests in SmokeTestWatcherWithSecurityIT have been failing daily for the last few weeks.

• testSearchInputWithInsufficientPrivileges:
  LINK REDACTED

• testIndexActionHasPermissions:
  LINK REDACTED

Output:

12:09:37 [2018-03-14T12:08:40,747][ERROR][o.e.x.w.a.i.IndexActionFactory] [node-0] failed to execute action [my_watch/index]
12:09:37 org.elasticsearch.ElasticsearchSecurityException: action [indices:data/write/bulk[s]] is unauthorized for user [watcher_manager]
12:09:37 	at org.elasticsearch.xpack.core.security.support.Exceptions.authorizationError(Exceptions.java:42) ~[?:?]
12:09:37 	at org.elasticsearch.xpack.security.authz.AuthorizationService.denialException(AuthorizationService.java:595) ~[?:?]
12:09:37 	at org.elasticsearch.xpack.security.authz.AuthorizationService.denial(AuthorizationService.java:565) ~[?:?]
12:09:37 	at org.elasticsearch.xpack.security.authz.AuthorizationService.authorize(AuthorizationService.java:310) ~[?:?]
12:09:37 	at org.elasticsearch.xpack.security.action.filter.SecurityActionFilter.lambda$authorizeRequest$4(SecurityActionFilter.java:176) ~[?:?]
12:09:37 	at org.elasticsearch.xpack.security.authz.AuthorizationUtils$AsyncAuthorizer.maybeRun(AuthorizationUtils.java:185) ~[?:?]
12:09:37 	at org.elasticsearch.xpack.security.authz.AuthorizationUtils$AsyncAuthorizer.setRunAsRoles(AuthorizationUtils.java:179) ~[?:?]
12:09:37 	at org.elasticsearch.xpack.security.authz.AuthorizationUtils$AsyncAuthorizer.authorize(AuthorizationUtils.java:167) ~[?:?]
....

[elasticmachine]

Original comment by @albertzaharovits:

I have came upon several such failures:
LINK REDACTED
LINK REDACTED
LINK REDACTED
which don't reproduce locally.

./gradlew :x-pack-elasticsearch:qa:smoke-test-watcher-with-security:integTestRunner \
  -Dtests.seed=E4F4AFFF2B7ABA44 \
  -Dtests.class=org.elasticsearch.smoketest.SmokeTestWatcherWithSecurityIT \
  -Dtests.method="testIndexActionInsufficientPrivileges" \
  -Dtests.security.manager=true \
  -Dtests.locale=ar-IQ \
  -Dtests.timezone=America/Indiana/Indianapolis

The error is as before:

10:18:12 org.elasticsearch.ElasticsearchSecurityException: action [indices:data/write/bulk[s]] is unauthorized for user [watcher_manager]
10:18:12 	at org.elasticsearch.xpack.core.security.support.Exceptions.authorizationError(Exceptions.java:42) ~[?:?]
10:18:12 	at org.elasticsearch.xpack.security.authz.AuthorizationService.denialException(AuthorizationService.java:586) ~[?:?]
10:18:12 	at org.elasticsearch.xpack.security.authz.AuthorizationService.denial(AuthorizationService.java:564) ~[?:?]
10:18:12 	at org.elasticsearch.xpack.security.authz.AuthorizationService.authorize(AuthorizationService.java:309) ~[?:?]
10:18:12 	at org.elasticsearch.xpack.security.action.filter.SecurityActionFilter.lambda$authorizeRequest$4(SecurityActionFilter.java:183) ~[?:?]
10:18:12 	at org.elasticsearch.xpack.security.authz.AuthorizationUtils$AsyncAuthorizer.maybeRun(AuthorizationUtils.java:185) ~[?:?]
10:18:12 	at org.elasticsearch.xpack.security.authz.AuthorizationUtils$AsyncAuthorizer.setRunAsRoles(AuthorizationUtils.java:179) ~[?:?]
10:18:12 	at org.elasticsearch.xpack.security.authz.AuthorizationUtils$AsyncAuthorizer.authorize(AuthorizationUtils.java:167) ~[?:?]
10:18:12 	at org.elasticsearch.xpack.security.action.filter.SecurityActionFilter.authorizeRequest(SecurityActionFilter.java:195) ~[?:?]
10:18:12 	at org.elasticsearch.xpack.security.action.filter.SecurityActionFilter.lambda$applyInternal$3(SecurityActionFilter.java:173) ~[?:?]
10:18:12 	at org.elasticsearch.action.ActionListener$1.onResponse(ActionListener.java:60) ~[elasticsearch-7.0.0-alpha1-SNAPSHOT.jar:7.0.0-alpha1-SNAPSHOT]
10:18:12 	at org.elasticsearch.xpack.security.authc.AuthenticationService$Authenticator.lambda$authenticateAsync$2(AuthenticationService.java:184) ~[?:?]
10:18:12 	at org.elasticsearch.xpack.security.authc.AuthenticationService$Authenticator.lambda$lookForExistingAuthentication$4(AuthenticationService.java:217) ~[?:?]
10:18:12 	at org.elasticsearch.xpack.security.authc.AuthenticationService$Authenticator.lookForExistingAuthentication(AuthenticationService.java:228) ~[?:?]
10:18:12 	at org.elasticsearch.xpack.security.authc.AuthenticationService$Authenticator.authenticateAsync(AuthenticationService.java:182) ~[?:?]
10:18:12 	at org.elasticsearch.xpack.security.authc.AuthenticationService$Authenticator.access$000(AuthenticationService.java:143) ~[?:?]

But I suspect there is a race condition with the .security index not being available:

10:18:12 ERROR   10.4s | SmokeTestWatcherWithSecurityIT.testIndexActionInsufficientPrivileges <<< FAILURES!
10:18:12    > Throwable LINK REDACTED: java.lang.AssertionError: 
10:18:12    > Expected: is "started"
10:18:12    >      but: was "stopped"
10:18:12    > 	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
10:18:12    > 	at org.elasticsearch.smoketest.SmokeTestWatcherWithSecurityIT.lambda$startWatcher$0(SmokeTestWatcherWithSecurityIT.java:74)
10:18:12   2> NOTE: leaving temporary files on disk at: /var/lib/jenkins/workspace/elastic+x-pack-elasticsearch+master+periodic/elasticsearch-extra/x-pack-elasticsearch/qa/smoke-test-watcher-with-security/build/testrun/integTestRunner/J0/temp/org.elasticsearch.smoketest.SmokeTestWatcherWithSecurityIT_E4F4AFFF2B7ABA44-001
10:18:12    > 	at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:734)
10:18:12   2> NOTE: test params are: codec=Asserting(Lucene70), sim=RandomSimilarity(queryNorm=false): {}, locale=ar-IQ, timezone=America/Indiana/Indianapolis
10:18:12   2> NOTE: Linux 4.4.0-1048-aws amd64/Oracle Corporation 1.8.0_162 (64-bit)/cpus=4,threads=1,free=377815112,total=514850816
10:18:12   2> NOTE: All tests run in this JVM: [SmokeTestWatcherWithSecurityClientYamlTestSuiteIT, SmokeTestWatcherWithSecurityIT]
10:18:12    > 	at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:708)
10:18:12    > 	at org.elasticsearch.smoketest.SmokeTestWatcherWithSecurityIT.startWatcher(SmokeTestWatcherWithSecurityIT.java:63)
10:18:12    > 	at java.lang.Thread.run(Thread.java:748)
10:18:12    > 	Suppressed: java.lang.AssertionError: 
10:18:12    > Expected: is "started"
10:18:12    >      but: was "stopping"
10:18:12    > 		at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
10:18:12    > 		at org.elasticsearch.smoketest.SmokeTestWatcherWithSecurityIT.lambda$startWatcher$0(SmokeTestWatcherWithSecurityIT.java:74)
10:18:12    > 		at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:722)
10:18:12    > 		... 38 more
10:18:12    > 	Suppressed: java.lang.AssertionError: 
10:18:12    > Expected: is "started"
10:18:12    >      but: was "stopping"
10:18:12    > 		at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
10:18:12    > 		at org.elasticsearch.smoketest.SmokeTestWatcherWithSecurityIT.lambda$startWatcher$0(SmokeTestWatcherWithSecurityIT.java:74)
10:18:12    > 		at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:722)
10:18:12    > 		... 38 more
10:18:12    > 	Suppressed: java.lang.AssertionError: 
10:18:12    > Expected: is "started"
10:18:12    >      but: was "stopping"
10:18:12    > 		at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
10:18:12    > 		at org.elasticsearch.smoketest.SmokeTestWatcherWithSecurityIT.lambda$startWatcher$0(SmokeTestWatcherWithSecurityIT.java:74)
10:18:12    > 		at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:722)
10:18:12    > 		... 38 more
10:18:12    > 	Suppressed: java.lang.AssertionError: 
10:18:12    > Expected: is "started"
10:18:12    >      but: was "stopping"
10:18:12    > 		at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
10:18:12    > 		at org.elasticsearch.smoketest.SmokeTestWatcherWithSecurityIT.lambda$startWatcher$0(SmokeTestWatcherWithSecurityIT.java:74)
10:18:12    > 		at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:722)
10:18:12    > 		... 38 more
10:18:12    > 	Suppressed: java.lang.AssertionError: 
10:18:12    > Expected: is "started"
10:18:12    >      but: was "stopping"
10:18:12    > 		at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
10:18:12    > 		at org.elasticsearch.smoketest.SmokeTestWatcherWithSecurityIT.lambda$startWatcher$0(SmokeTestWatcherWithSecurityIT.java:74)
10:18:12    > 		at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:722)
10:18:12    > 		... 38 more
10:18:12    > 	Suppressed: java.lang.AssertionError: 
10:18:12    > Expected: is "started"
10:18:12    >      but: was "stopping"
10:18:12    > 		at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
10:18:12    > 		at org.elasticsearch.smoketest.SmokeTestWatcherWithSecurityIT.lambda$startWatcher$0(SmokeTestWatcherWithSecurityIT.java:74)
10:18:12    > 		at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:722)
10:18:12    > 		... 38 more
10:18:12    > 	Suppressed: java.lang.AssertionError: 
10:18:12    > Expected: is "started"
10:18:12    >      but: was "stopping"
10:18:12    > 		at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
10:18:12    > 		at org.elasticsearch.smoketest.SmokeTestWatcherWithSecurityIT.lambda$startWatcher$0(SmokeTestWatcherWithSecurityIT.java:74)
10:18:12    > 		at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:722)
10:18:12    > 		... 38 more
10:18:12    > 	Suppressed: java.lang.AssertionError: 
10:18:12    > Expected: is "started"
10:18:12    >      but: was "stopping"
10:18:12    > 		at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
10:18:12    > 		at org.elasticsearch.smoketest.SmokeTestWatcherWithSecurityIT.lambda$startWatcher$0(SmokeTestWatcherWithSecurityIT.java:74)
10:18:12    > 		at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:722)
10:18:12    > 		... 38 more
10:18:12    > 	Suppressed: java.lang.AssertionError: 
10:18:12    > Expected: is "started"
10:18:12    >      but: was "stopping"
10:18:12    > 		at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
10:18:12    > 		at org.elasticsearch.smoketest.SmokeTestWatcherWithSecurityIT.lambda$startWatcher$0(SmokeTestWatcherWithSecurityIT.java:74)
10:18:12    > 		at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:722)
10:18:12    > 		... 38 more
10:18:12    > 	Suppressed: java.lang.AssertionError: 
10:18:12    > Expected: is "started"
10:18:12    >      but: was "stopped"
10:18:12    > 		at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
10:18:12    > 		at org.elasticsearch.smoketest.SmokeTestWatcherWithSecurityIT.lambda$startWatcher$0(SmokeTestWatcherWithSecurityIT.java:74)
10:18:12    > 		at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:722)
10:18:12    > 		... 38 more
10:18:12    > 	Suppressed: java.lang.AssertionError: 
10:18:12    > Expected: is "started"
10:18:12    >      but: was "stopped"
10:18:12    > 		at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
10:18:12    > 		at org.elasticsearch.smoketest.SmokeTestWatcherWithSecurityIT.lambda$startWatcher$0(SmokeTestWatcherWithSecurityIT.java:74)
10:18:12    > 		at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:722)
10:18:12    > 		... 38 more
10:18:12    > 	Suppressed: java.lang.AssertionError: 
10:18:12    > Expected: is "started"
10:18:12    >      but: was "stopped"
10:18:12    > 		at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
10:18:12    > 		at org.elasticsearch.smoketest.SmokeTestWatcherWithSecurityIT.lambda$startWatcher$0(SmokeTestWatcherWithSecurityIT.java:74)
10:18:12    > 		at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:722)
10:18:12    > 		... 38 more
10:18:12    > 	Suppressed: java.lang.AssertionError: 
10:18:12    > Expected: is "started"
10:18:12    >      but: was "stopped"
10:18:12    > 		at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
10:18:12    > 		at org.elasticsearch.smoketest.SmokeTestWatcherWithSecurityIT.lambda$startWatcher$0(SmokeTestWatcherWithSecurityIT.java:74)
10:18:12    > 		at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:722)
10:18:12    > 		... 38 moreThrowable LINK REDACTED: org.elasticsearch.client.ResponseException: method [DELETE], host [http://[::1]:34429], URI [_xpack/watcher/watch/my_watch], status line [HTTP/1.1 404 Not Found]
10:18:12    > {"error":{"root_cause":[{"type":"index_not_found_exception","reason":"no such index","resource.type":"index_expression","resource.id":".watches","index_uuid":"_na_","index":".watches"}],"type":"index_not_found_exception","reason":"no such index","resource.type":"index_expression","resource.id":".watches","index_uuid":"_na_","index":".watches"},"status":404}
10:18:12    > 	at org.elasticsearch.client.RestClient$SyncResponseListener.get(RestClient.java:705)
10:18:12    > 	at org.elasticsearch.client.RestClient.performRequest(RestClient.java:235)
10:18:12    > 	at org.elasticsearch.client.RestClient.performRequest(RestClient.java:198)
10:18:12    > 	at org.elasticsearch.client.RestClient.performRequest(RestClient.java:160)
10:18:12    > 	at org.elasticsearch.smoketest.SmokeTestWatcherWithSecurityIT.stopWatcher(SmokeTestWatcherWithSecurityIT.java:83)
10:18:12    > 	at java.lang.Thread.run(Thread.java:748)
10:18:12    > Caused by: org.elasticsearch.client.ResponseException: method [DELETE], host [http://[::1]:34429], URI [_xpack/watcher/watch/my_watch], status line [HTTP/1.1 404 Not Found]
10:18:12    > {"error":{"root_cause":[{"type":"index_not_found_exception","reason":"no such index","resource.type":"index_expression","resource.id":".watches","index_uuid":"_na_","index":".watches"}],"type":"index_not_found_exception","reason":"no such index","resource.type":"index_expression","resource.id":".watches","index_uuid":"_na_","index":".watches"},"status":404}

[elasticmachine]

Original comment by @javanna:

Another failure similar to the last one posted by Albert:
LINK REDACTED

[elasticmachine]

Original comment by @javanna:

And another occurrence: LINK REDACTED