SQL: JdbcSecurityIT fail when reading audit logging files at rollover time

[astefan]

This seems to be a consequence of this fix. The test fails at midnight, so it happens rather rarely. The failure is different than the previous issue, but still they are very much related.

REPRODUCE WITH: ./gradlew :x-pack:plugin:sql:qa:security:with-ssl:integTestRunner \
  -Dtests.seed=CDAFA8CD10B79641 \
  -Dtests.class=org.elasticsearch.xpack.sql.qa.security.JdbcSecurityIT \
  -Dtests.method="testDescribeWithWrongAccess" \
  -Dtests.security.manager=true \
  -Dtests.locale=es-CO \
  -Dtests.timezone=Africa/Nouakchott \
  -Dcompiler.java=11 \
  -Druntime.java=8

java.lang.IllegalArgumentException: Unrecognized log: vent.type":"transport", "event.action":"access_granted", "user.name":"test_admin", "user.realm":"default_file", "user.roles":["superuser"], "origin.type":"rest", "origin.address":"[::1]:52132", "request.id":"ddAjKxaeTLKXBnuomTepAA", "action":"cluster:monitor/task", "request.name":"PendingClusterTasksRequest"}
	at __randomizedtesting.SeedInfo.seed([CDAFA8CD10B79641:F8A0C0F4F35B2E2F]:0)
	at org.elasticsearch.xpack.sql.qa.security.SqlSecurityTestCase$AuditLogAsserter.lambda$assertLogs$2(SqlSecurityTestCase.java:652)
	at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:856)
	at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:842)
	at org.elasticsearch.xpack.sql.qa.security.SqlSecurityTestCase$AuditLogAsserter.assertLogs(SqlSecurityTestCase.java:570)
	at org.elasticsearch.xpack.sql.qa.security.SqlSecurityTestCase.testDescribeWithWrongAccess(SqlSecurityTestCase.java:447)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1750)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:938)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:974)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:988)
	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:368)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:817)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:468)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:947)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:832)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:883)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:894)
	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 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:368)
	at java.lang.Thread.run(Thread.java:748)
Caused by: ElasticsearchParseException[Failed to parse content to map]; nested: JsonParseException[Unrecognized token 'vent': was expecting ('true', 'false' or 'null')
 at [Source: java.io.StringReader@6e891a7c; line: 1, column: 5]];
	at org.elasticsearch.common.xcontent.XContentHelper.convertToMap(XContentHelper.java:131)
	at org.elasticsearch.xpack.sql.qa.security.SqlSecurityTestCase$AuditLogAsserter.lambda$assertLogs$2(SqlSecurityTestCase.java:621)
	... 41 more
Caused by: com.fasterxml.jackson.core.JsonParseException: Unrecognized token 'vent': was expecting ('true', 'false' or 'null')
 at [Source: java.io.StringReader@6e891a7c; line: 1, column: 5]
	at com.fasterxml.jackson.core.JsonParser._constructError(JsonParser.java:1702)
	at com.fasterxml.jackson.core.base.ParserMinimalBase._reportError(ParserMinimalBase.java:558)
	at com.fasterxml.jackson.core.json.ReaderBasedJsonParser._reportInvalidToken(ReaderBasedJsonParser.java:2839)
	at com.fasterxml.jackson.core.json.ReaderBasedJsonParser._handleOddValue(ReaderBasedJsonParser.java:1903)
	at com.fasterxml.jackson.core.json.ReaderBasedJsonParser.nextToken(ReaderBasedJsonParser.java:749)
	at org.elasticsearch.common.xcontent.json.JsonXContentParser.nextToken(JsonXContentParser.java:52)
	at org.elasticsearch.common.xcontent.support.AbstractXContentParser.readMap(AbstractXContentParser.java:326)
	at org.elasticsearch.common.xcontent.support.AbstractXContentParser.readMap(AbstractXContentParser.java:299)
	at org.elasticsearch.common.xcontent.support.AbstractXContentParser.map(AbstractXContentParser.java:254)
	at org.elasticsearch.common.xcontent.XContentHelper.convertToMap(XContentHelper.java:129)
	... 42 more

The test method is irrelevant, it matters when the audit logging files reading happens.

[elasticmachine]

Pinging @elastic/es-search

[danielmitterdorfer]

We have another failure in https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+intake/3147:

Error message

java.lang.IllegalArgumentException: Unrecognized log: ywzj3cGpQ", "event.type":"transport", "event.action":"access_granted", "user.name":"test_admin", "user.realm":"default_file", "user.roles":["superuser"], "origin.type":"rest", "origin.address":"[::1]:38132", "request.id":"iagGJVHIRli9NoJywYOU8Q", "action":"cluster:monitor/state", "request.name":"ClusterStateRequest", "indices":[]}

Reproduction line

./gradlew :x-pack:plugin:sql:qa:security:with-ssl:integTestRunner --tests "org.elasticsearch.xpack.sql.qa.security.JdbcSecurityIT.testDescribeWorksAsAdmin" -Dtests.seed=817215EC9743C1CF -Dtests.security.manager=true -Dtests.locale=bn-BD -Dtests.timezone=America/Denver -Dcompiler.java=12 -Druntime.java=11

Full stack trace

Click for Details

java.lang.IllegalArgumentException: Unrecognized log: ywzj3cGpQ", "event.type":"transport", "event.action":"access_granted", "user.name":"test_admin", "user.realm":"default_file", "user.roles":["superuser"], "origin.type":"rest", "origin.address":"[::1]:38132", "request.id":"iagGJVHIRli9NoJywYOU8Q", "action":"cluster:monitor/state", "request.name":"ClusterStateRequest", "indices":[]}
	at __randomizedtesting.SeedInfo.seed([817215EC9743C1CF:311A6174433AA1E0]:0)
	at org.elasticsearch.xpack.sql.qa.security.SqlSecurityTestCase$AuditLogAsserter.lambda$assertLogs$2(SqlSecurityTestCase.java:652)
	at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:850)
	at org.elasticsearch.test.ESTestCase.assertBusy(ESTestCase.java:836)
	at org.elasticsearch.xpack.sql.qa.security.SqlSecurityTestCase$AuditLogAsserter.assertLogs(SqlSecurityTestCase.java:571)
	at org.elasticsearch.xpack.sql.qa.security.SqlSecurityTestCase.testDescribeWorksAsAdmin(SqlSecurityTestCase.java:417)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1750)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:938)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:974)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:988)
	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:368)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:817)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:468)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:947)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:832)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:883)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:894)
	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:368)
	at java.base/java.lang.Thread.run(Thread.java:834)
Caused by: ElasticsearchParseException[Failed to parse content to map]; nested: JsonParseException[Unrecognized token 'ywzj3cGpQ': was expecting ('true', 'false' or 'null')
 at [Source: java.io.StringReader@8c9568f; line: 1, column: 10]];
	at org.elasticsearch.common.xcontent.XContentHelper.convertToMap(XContentHelper.java:131)
	at org.elasticsearch.xpack.sql.qa.security.SqlSecurityTestCase$AuditLogAsserter.lambda$assertLogs$2(SqlSecurityTestCase.java:622)
	... 40 more
Caused by: com.fasterxml.jackson.core.JsonParseException: Unrecognized token 'ywzj3cGpQ': was expecting ('true', 'false' or 'null')
 at [Source: java.io.StringReader@8c9568f; line: 1, column: 10]
	at com.fasterxml.jackson.core.JsonParser._constructError(JsonParser.java:1702)
	at com.fasterxml.jackson.core.base.ParserMinimalBase._reportError(ParserMinimalBase.java:558)
	at com.fasterxml.jackson.core.json.ReaderBasedJsonParser._reportInvalidToken(ReaderBasedJsonParser.java:2839)
	at com.fasterxml.jackson.core.json.ReaderBasedJsonParser._handleOddValue(ReaderBasedJsonParser.java:1903)
	at com.fasterxml.jackson.core.json.ReaderBasedJsonParser.nextToken(ReaderBasedJsonParser.java:749)
	at org.elasticsearch.common.xcontent.json.JsonXContentParser.nextToken(JsonXContentParser.java:52)
	at org.elasticsearch.common.xcontent.support.AbstractXContentParser.readMap(AbstractXContentParser.java:336)
	at org.elasticsearch.common.xcontent.support.AbstractXContentParser.readMap(AbstractXContentParser.java:309)
	at org.elasticsearch.common.xcontent.support.AbstractXContentParser.map(AbstractXContentParser.java:264)
	at org.elasticsearch.common.xcontent.XContentHelper.convertToMap(XContentHelper.java:129)
	... 41 more

I'll mute the entire suite now. - Update: Discussed with @astefan not to mute the test suite because it is only failing rarely and we would risk not detecting other issues.