[CI] JdbcSecurityIT testQueryDocumentExcluded failing

[iverase]

I think there was a similar occurrence on June 1st: https://gradle-enterprise.elastic.co/s/kmwjw4dcwdppk

Build scan:
https://gradle-enterprise.elastic.co/s/3gt7diubtz7mu/tests/:x-pack:plugin:sql:qa:server:security:with-ssl:integTest/org.elasticsearch.xpack.sql.qa.security.JdbcSecurityIT/testQueryDocumentExcluded

Reproduction line:
./gradlew ':x-pack:plugin:sql:qa:server:security:with-ssl:integTest' --tests "org.elasticsearch.xpack.sql.qa.security.JdbcSecurityIT.testQueryDocumentExcluded" -Dtests.seed=68E003C7EDCA036 -Dtests.locale=zh -Dtests.timezone=Australia/Yancowinna -Druntime.java=11

Applicable branches:
master

Reproduces locally?:
No

Failure history:
https://gradle-enterprise.elastic.co/scans/tests?tests.container=org.elasticsearch.xpack.sql.qa.security.JdbcSecurityIT&tests.test=testQueryDocumentExcluded

Failure excerpt:

java.lang.AssertionError: Some checkers [0, 1, 2, 3] didn't match any logs. All logs:  none!
Remaining logs:  none!

  at __randomizedtesting.SeedInfo.seed([68E003C7EDCA036:B17D9F735B81E0BA]:0)
  at org.junit.Assert.fail(Assert.java:88)
  at org.elasticsearch.xpack.sql.qa.security.SqlSecurityTestCase$AuditLogAsserter.lambda$assertLogs$3(SqlSecurityTestCase.java:677)
  at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:965)
  at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:938)
  at org.elasticsearch.xpack.sql.qa.security.SqlSecurityTestCase$AuditLogAsserter.assertLogs(SqlSecurityTestCase.java:575)
  at org.elasticsearch.xpack.sql.qa.security.SqlSecurityTestCase.testQueryDocumentExcluded(SqlSecurityTestCase.java:362)
  at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java:-2)
  at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
  at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
  at java.lang.reflect.Method.invoke(Method.java:566)
  at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1758)
  at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:946)
  at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:982)
  at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:996)
  at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
  at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:49)
  at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
  at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:48)
  at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
  at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
  at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
  at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:375)
  at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:824)
  at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:475)
  at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:955)
  at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:840)
  at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:891)
  at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:902)
  at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
  at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
  at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:41)
  at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
  at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
  at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
  at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
  at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53)
  at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
  at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
  at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:54)
  at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
  at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:375)
  at com.carrotsearch.randomizedtesting.ThreadLeakControl.lambda$forkTimeoutingTask$0(ThreadLeakControl.java:831)
  at java.lang.Thread.run(Thread.java:829)

[elasticmachine]

Pinging @elastic/es-ql (Team:QL)

[astefan]

One more (recent) failure. Probably similar, if not the same: https://gradle-enterprise.elastic.co/s/kosk7c47y2ujy

[astefan]

And a bit older one: https://gradle-enterprise.elastic.co/s/ov4hrnxx2vnxg

[ywangd]

Another one: https://gradle-enterprise.elastic.co/s/6kgjg3tj2tl5u/tests/failed

The above build scan has a few other test failures. The error message is:

java.lang.AssertionError: Previous test had an audit-related failure. All subsequent audit related assertions are bogus because we can't guarantee that we fully cleaned up after the last test.

Seems like a test setup issue. So it might be cascading failures due to failure of testQueryDocumentExcluded.

[astefan]

This test is about reading and making assertions on audit logging. If we expect some audit log lines to be there but they are not, then one test fails. The subsequent tests will fail as well, because we take the logs line by line and if one of them has a breakage, that one cascades on the following ones.

The likely reason for the failures, because it happens so rarely at apparently top of the hour timestamps, it could be related to the rollover process. We've had a similar bug in the past in the test itself, it was fixed and for a long time there were no further failures. Until this issue. We didn't change these tests in a very long time, so it's likely to be related to the rollover process or the content of the logs when the rollover happens.

[astefan]

Leaving here some snippets from various failures:

  1> [2021-07-19T17:59:59,017][INFO ][o.e.x.s.q.s.JdbcSecurityIT] [testShowTablesWithLimitedAccessUnaccessableIndex] after test
  1> [2021-07-19T17:59:59,036][INFO ][o.e.x.s.q.s.JdbcSecurityIT] [testShowTablesWorksAsFullAccess] before test
  1> [2021-07-19T17:59:59,959][INFO ][o.e.x.s.q.s.JdbcSecurityIT] [testShowTablesWorksAsFullAccess] after test
  1> [2021-07-19T17:59:59,977][INFO ][o.e.x.s.q.s.JdbcSecurityIT] [testQueryDocumentExcluded] before test
  1> [2021-07-19T18:00:10,708][WARN ][o.e.x.s.q.s.JdbcSecurityIT] [testQueryDocumentExcluded] Failed to find an audit log. Skipping remaining tests in this class after this the missing auditlogs could turn up later.
  1> [2021-07-19T18:00:10,902][INFO ][o.e.x.s.q.s.JdbcSecurityIT] [testQueryDocumentExcluded] after test
  2> REPRODUCE WITH: ./gradlew ':x-pack:plugin:sql:qa:server:security:with-ssl:integTest' --tests "org.elasticsearch.xpack.sql.qa.security.JdbcSecurityIT.testQueryDocumentExcluded" -Dtests.seed=A7CC4DDCA50FB1EA -Dtests.locale=hu -Dtests.timezone=Pacific/Easter -Druntime.java=11
  2> java.lang.AssertionError: Some checkers [0, 1, 2, 3] didn't match any logs. All logs:  none!
    Remaining logs:  none!
        at __randomizedtesting.SeedInfo.seed([A7CC4DDCA50FB1EA:103FD2938052F166]:0)
        at org.junit.Assert.fail(Assert.java:88)
        at org.elasticsearch.xpack.sql.qa.security.SqlSecurityTestCase$AuditLogAsserter.lambda$assertLogs$3(SqlSecurityTestCase.java:677)
        at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:973)
        at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:946)
        at org.elasticsearch.xpack.sql.qa.security.SqlSecurityTestCase$AuditLogAsserter.assertLogs(SqlSecurityTestCase.java:575)
        at org.elasticsearch.xpack.sql.qa.security.SqlSecurityTestCase.testQueryDocumentExcluded(SqlSecurityTestCase.java:362)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)

  1> [2021-06-07T01:59:59,200][INFO ][o.e.x.s.q.s.JdbcSecurityIT] [testShowTablesWithNoAccess] before test
  1> [2021-06-07T01:59:59,957][INFO ][o.e.x.s.q.s.JdbcSecurityIT] [testShowTablesWithNoAccess] after test
  1> [2021-06-07T01:59:59,984][INFO ][o.e.x.s.q.s.JdbcSecurityIT] [testScrollWithSingleFieldExcepted] before test
  1> [2021-06-07T02:00:10,368][WARN ][o.e.x.s.q.s.JdbcSecurityIT] [testScrollWithSingleFieldExcepted] Failed to find an audit log. Skipping remaining tests in this class after this the missing auditlogs could turn up later.
  1> [2021-06-07T02:00:10,788][INFO ][o.e.x.s.q.s.JdbcSecurityIT] [testScrollWithSingleFieldExcepted] after test
  2> REPRODUCE WITH: gradlew ':x-pack:plugin:sql:qa:server:security:without-ssl:integTest' --tests "org.elasticsearch.xpack.sql.qa.security.JdbcSecurityIT.testScrollWithSingleFieldExcepted" -Dtests.seed=B47328DD358C3E5D -Dtests.locale=en-AU -Dtests.timezone=Etc/GMT-2 -Druntime.java=11  2> 
  2> 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([B47328DD358C3E5D:619AC14499317F61]:0)
        at org.junit.Assert.fail(Assert.java:88)
        at org.elasticsearch.xpack.sql.qa.security.SqlSecurityTestCase$AuditLogAsserter.lambda$assertLogs$3(SqlSecurityTestCase.java:677)
        at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:973)
        at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:946)
        at org.elasticsearch.xpack.sql.qa.security.SqlSecurityTestCase$AuditLogAsserter.assertLogs(SqlSecurityTestCase.java:575)
        at org.elasticsearch.xpack.sql.qa.security.SqlSecurityTestCase.testScrollWithSingleFieldExcepted(SqlSecurityTestCase.java:340)

  1> [2021-06-08T01:59:59,129][INFO ][o.e.x.s.q.s.JdbcSecurityIT] [testDescribeWithWrongAccess] before test
  1> [2021-06-08T01:59:59,624][INFO ][o.e.x.s.q.s.JdbcSecurityIT] [testDescribeWithWrongAccess] after test
  1> [2021-06-08T01:59:59,639][INFO ][o.e.x.s.q.s.JdbcSecurityIT] [testScrollWithSingleFieldExcepted] before test
  1> [2021-06-08T02:00:10,337][WARN ][o.e.x.s.q.s.JdbcSecurityIT] [testScrollWithSingleFieldExcepted] Failed to find an audit log. Skipping remaining tests in this class after this the missing auditlogs could turn up later.
  1> [2021-06-08T02:00:10,429][INFO ][o.e.x.s.q.s.JdbcSecurityIT] [testScrollWithSingleFieldExcepted] after test
  2> REPRODUCE WITH: ./gradlew ':x-pack:plugin:sql:qa:server:security:with-ssl:integTest' --tests "org.elasticsearch.xpack.sql.qa.security.JdbcSecurityIT.testScrollWithSingleFieldExcepted" -Dtests.seed=E18AAF3CA97F64D7 -Dtests.locale=es-CR -Dtests.timezone=Arctic/Longyearbyen -Druntime.java=17
  2> 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([E18AAF3CA97F64D7:346346A505C225EB]:0)
        at org.junit.Assert.fail(Assert.java:88)
        at org.elasticsearch.xpack.sql.qa.security.SqlSecurityTestCase$AuditLogAsserter.lambda$assertLogs$3(SqlSecurityTestCase.java:677)
        at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:973)
        at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:946)
        at org.elasticsearch.xpack.sql.qa.security.SqlSecurityTestCase$AuditLogAsserter.assertLogs(SqlSecurityTestCase.java:575)
        at org.elasticsearch.xpack.sql.qa.security.SqlSecurityTestCase.testScrollWithSingleFieldExcepted(SqlSecurityTestCase.java:340)

  1> [2021-07-19T17:59:58,091][INFO ][o.e.x.s.q.s.JdbcSecurityIT] [testShowTablesWithLimitedAccessUnaccessableIndex] before test
  1> [2021-07-19T17:59:59,017][INFO ][o.e.x.s.q.s.JdbcSecurityIT] [testShowTablesWithLimitedAccessUnaccessableIndex] after test
  1> [2021-07-19T17:59:59,036][INFO ][o.e.x.s.q.s.JdbcSecurityIT] [testShowTablesWorksAsFullAccess] before test
  1> [2021-07-19T17:59:59,959][INFO ][o.e.x.s.q.s.JdbcSecurityIT] [testShowTablesWorksAsFullAccess] after test
  1> [2021-07-19T17:59:59,977][INFO ][o.e.x.s.q.s.JdbcSecurityIT] [testQueryDocumentExcluded] before test
  1> [2021-07-19T18:00:10,708][WARN ][o.e.x.s.q.s.JdbcSecurityIT] [testQueryDocumentExcluded] Failed to find an audit log. Skipping remaining tests in this class after this the missing auditlogs could turn up later.
  1> [2021-07-19T18:00:10,902][INFO ][o.e.x.s.q.s.JdbcSecurityIT] [testQueryDocumentExcluded] after test
  2> REPRODUCE WITH: ./gradlew ':x-pack:plugin:sql:qa:server:security:with-ssl:integTest' --tests "org.elasticsearch.xpack.sql.qa.security.JdbcSecurityIT.testQueryDocumentExcluded" -Dtests.seed=A7CC4DDCA50FB1EA -Dtests.locale=hu -Dtests.timezone=Pacific/Easter -Druntime.java=11
  2> java.lang.AssertionError: Some checkers [0, 1, 2, 3] didn't match any logs. All logs:  none!
    Remaining logs:  none!
        at __randomizedtesting.SeedInfo.seed([A7CC4DDCA50FB1EA:103FD2938052F166]:0)
        at org.junit.Assert.fail(Assert.java:88)
        at org.elasticsearch.xpack.sql.qa.security.SqlSecurityTestCase$AuditLogAsserter.lambda$assertLogs$3(SqlSecurityTestCase.java:677)
        at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:973)
        at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:946)
        at org.elasticsearch.xpack.sql.qa.security.SqlSecurityTestCase$AuditLogAsserter.assertLogs(SqlSecurityTestCase.java:575)
        at org.elasticsearch.xpack.sql.qa.security.SqlSecurityTestCase.testQueryDocumentExcluded(SqlSecurityTestCase.java:362)

[valeriy42]

Another related test failure today: https://gradle-enterprise.elastic.co/s/fjcxmwocra4o4

[ywangd]

Another one: https://gradle-enterprise.elastic.co/s/5koqsxhkrfr6i