Failures in RestSqlSecurityIT on 6.4

[cbuescher]

Build: https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+6.4+multijob-unix-compatibility/os=opensuse/19/console

Several failures, most seem follow ups of the first erro. I couldn't reproduce locally so far:

REPRODUCE WITH: ./gradlew :x-pack:qa:sql:security:no-ssl:integTestRunner \
  -Dtests.seed=945E72B46191E48E \
  -Dtests.class=org.elasticsearch.xpack.qa.sql.security.RestSqlSecurityIT \
  -Dtests.method="testScrollWithFullAccess" \
  -Dtests.security.manager=true \
  -Dtests.locale=ca-ES \
  -Dtests.timezone=US/Aleutian

REPRODUCE WITH: ./gradlew :x-pack:qa:sql:security:no-ssl:integTestRunner \
  -Dtests.seed=945E72B46191E48E \
  -Dtests.class=org.elasticsearch.xpack.qa.sql.security.RestSqlSecurityIT \
  -Dtests.method="testQueryWrongAccess" \
  -Dtests.security.manager=true \
  -Dtests.locale=ca-ES \
  -Dtests.timezone=US/Aleutian

REPRODUCE WITH: ./gradlew :x-pack:qa:sql:security:no-ssl:integTestRunner \
  -Dtests.seed=945E72B46191E48E \
  -Dtests.class=org.elasticsearch.xpack.qa.sql.security.RestSqlSecurityIT \
  -Dtests.method="testDescribeWithWrongAccess" \
  -Dtests.security.manager=true \
  -Dtests.locale=ca-ES \
  -Dtests.timezone=US/Aleutian

REPRODUCE WITH: ./gradlew :x-pack:qa:sql:security:no-ssl:integTestRunner \
  -Dtests.seed=945E72B46191E48E \
  -Dtests.class=org.elasticsearch.xpack.qa.sql.security.RestSqlSecurityIT \
  -Dtests.method="testQueryStringSingeFieldGrantedWrongRequested" \
  -Dtests.security.manager=true \
  -Dtests.locale=ca-ES \
  -Dtests.timezone=US/Aleutian

REPRODUCE WITH: ./gradlew :x-pack:qa:sql:security:no-ssl:integTestRunner \
  -Dtests.seed=945E72B46191E48E \
  -Dtests.class=org.elasticsearch.xpack.qa.sql.security.RestSqlSecurityIT \
  -Dtests.method="testQueryWithFullAccess" \
  -Dtests.security.manager=true \
  -Dtests.locale=ca-ES \
  -Dtests.timezone=US/Aleutian

REPRODUCE WITH: ./gradlew :x-pack:qa:sql:security:no-ssl:integTestRunner \
  -Dtests.seed=945E72B46191E48E \
  -Dtests.class=org.elasticsearch.xpack.qa.sql.security.RestSqlSecurityIT \
  -Dtests.method="testQuerySingleFieldExceptionedWrongRequested" \
  -Dtests.security.manager=true \
  -Dtests.locale=ca-ES \
  -Dtests.timezone=US/Aleutian

REPRODUCE WITH: ./gradlew :x-pack:qa:sql:security:no-ssl:integTestRunner \
  -Dtests.seed=945E72B46191E48E \
  -Dtests.class=org.elasticsearch.xpack.qa.sql.security.RestSqlSecurityIT \
  -Dtests.method="testScrollWithSingleFieldExcepted" \
  -Dtests.security.manager=true \
  -Dtests.locale=ca-ES \
  -Dtests.timezone=US/Aleutian

REPRODUCE WITH: ./gradlew :x-pack:qa:sql:security:no-ssl:integTestRunner \
  -Dtests.seed=945E72B46191E48E \
  -Dtests.class=org.elasticsearch.xpack.qa.sql.security.RestSqlSecurityIT \
  -Dtests.method="testShowTablesWithNoAccess" \
  -Dtests.security.manager=true \
  -Dtests.locale=ca-ES \
  -Dtests.timezone=US/Aleutian

REPRODUCE WITH: ./gradlew :x-pack:qa:sql:security:no-ssl:integTestRunner \
  -Dtests.seed=945E72B46191E48E \
  -Dtests.class=org.elasticsearch.xpack.qa.sql.security.RestSqlSecurityIT \
  -Dtests.method="testDescribeSingleFieldExcepted" \
  -Dtests.security.manager=true \
  -Dtests.locale=ca-ES \
  -Dtests.timezone=US/Aleutian

REPRODUCE WITH: ./gradlew :x-pack:qa:sql:security:no-ssl:integTestRunner \
  -Dtests.seed=945E72B46191E48E \
  -Dtests.class=org.elasticsearch.xpack.qa.sql.security.RestSqlSecurityIT \
  -Dtests.method="testQuerySingleFieldExcepted" \
  -Dtests.security.manager=true \
  -Dtests.locale=ca-ES \
  -Dtests.timezone=US/Aleutian

The first failure output looks like this:

02:00:12   1> [2018-09-23T14:59:59,867][INFO ][o.e.x.q.s.s.RestSqlSecurityIT] [testScrollWithFullAccess]: before test
02:00:12   1> [2018-09-23T15:00:10,011][WARN ][o.e.x.q.s.s.RestSqlSecurityIT] Failed to find an audit log. Skipping remaining tests in this class after this the missing auditlogs could turn up later.
02:00:12   1> [2018-09-23T15:00:10,051][INFO ][o.e.x.q.s.s.RestSqlSecurityIT] [testScrollWithFullAccess]: after test
02:00:12 FAILURE 10.2s | RestSqlSecurityIT.testScrollWithFullAccess <<< FAILURES!
02:00:12    > Throwable #1: java.lang.AssertionError: Some checkers [0, 1, 2, 3, 4, 5, 6, 7] didn't match any logs. All logs:  none!
02:00:12    > Remaining logs:  none!
02:00:12    > 	at __randomizedtesting.SeedInfo.seed([945E72B46191E48E:EC80BBC68369A732]:0)
02:00:12    > 	at org.elasticsearch.xpack.qa.sql.security.SqlSecurityTestCase$AuditLogAsserter.lambda$assertLogs$2(SqlSecurityTestCase.java:622)
02:00:12    > 	at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:830)
02:00:12    > 	at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:804)
02:00:12    > 	at org.elasticsearch.xpack.qa.sql.security.SqlSecurityTestCase$AuditLogAsserter.assertLogs(SqlSecurityTestCase.java:541)
02:00:12    > 	at org.elasticsearch.xpack.qa.sql.security.SqlSecurityTestCase.testScrollWithFullAccess(SqlSecurityTestCase.java:225)
02:00:12    > 	at java.lang.Thread.run(Thread.java:748)
02:00:12    > 	Suppressed: java.lang.AssertionError: Some checkers [0, 1, 2, 3, 4, 5, 6, 7] didn't match any logs. All logs:  none!
02:00:12    > Remaining logs:  none!
02:00:12    > 		at org.elasticsearch.xpack.qa.sql.security.SqlSecurityTestCase$AuditLogAsserter.lambda$assertLogs$2(SqlSecurityTestCase.java:622)

[elasticmachine]

Pinging @elastic/es-search-aggs

[elasticmachine]

Pinging @elastic/es-security

[colings86]

@costin Cold you look into these failures?

[droberts195]

Same thing in
https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+6.4+multijob-unix-compatibility/os=amazon/37/console

Exactly the same set of tests failed.

Again, the error for all failed tests is:

   > Throwable #1: java.lang.AssertionError: Some checkers [0, 1, 2, 3, 4, 5, 6, 7] didn't match any logs. All logs:  none!
   > Remaining logs:  none!
   > 	at __randomizedtesting.SeedInfo.seed([D8632DA396228436:F2F6FC242F76C07A]:0)
   > 	at org.elasticsearch.xpack.qa.sql.security.SqlSecurityTestCase$AuditLogAsserter.lambda$assertLogs$2(SqlSecurityTestCase.java:622)
   > 	at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:830)
   > 	at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:804)
   > 	at org.elasticsearch.xpack.qa.sql.security.SqlSecurityTestCase$AuditLogAsserter.assertLogs(SqlSecurityTestCase.java:541)

[astefan]

I've looked over this one and the assertion comes from an assertBusy() block which has a runtime of 10 seconds. From this block, the assertion comes from what seems to be an empty audit log file. The handling of an empty log file is not handled inside this block of code and I am not sure if it should be handled in any way (as the audit log shouldn't actually be empty?).

If the audit log is empty, some didn't go as planned during the test?
@nik9000 do you have any ideas why ^ might happen?
A more recent failure (where the full logs are still available) is here.

[nik9000]

I wonder if the audit log file rolled over. We don't handle that and I hadn't thought about it. But it's make sense. I'm not sure if it'd be easier to disable rolling for the test or to scan all of the files.

[astefan]

master (8.0.0): 75cb6b3
7.x (7.1.0): 6359d98
7.0 (7.0.0): 8cd20d1
6.7 (6.7.0): 5fed91e

[tvernum]

This is still failing on 6.6 so I opened #39615 for backport to that branch.
https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+6.6+multijob-unix-compatibility/os=ubuntu-18.04&&immutable/149/console