[CI] CliSecurityIT testDescribeDocumentExcluded failed with missing audit log

[droberts195]

Many tests in the CliSecurityIT suite failed in https://gradle-enterprise.elastic.co/s/3fgucfb5u5uki

However, all of them apart from 1 say:

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.

The root cause failure appears to be CliSecurityIT.testDescribeDocumentExcluded:

  1> [2019-10-16T02:52:08,327][INFO ][o.e.x.s.q.c.EmbeddedCli  ] [[Thread-49]] cli exited with code [0]
  1> [2019-10-16T02:52:18,688][WARN ][o.e.x.s.q.s.CliSecurityIT] [testDescribeWorksAsFullAccess] Failed to find an audit log. Skipping remaining tests in this class after this the missing auditlogs could turn up later.
  1> [2019-10-16T02:52:18,921][INFO ][o.e.x.s.q.s.CliSecurityIT] [testDescribeWorksAsFullAccess] after test
  2> REPRODUCE WITH: ./gradlew ':x-pack:plugin:sql:qa:security:with-ssl:integTestRunner' --tests "org.elasticsearch.xpack.sql.qa.security.CliSecurityIT.testDescribeWorksAsFullAccess" -Dtests.seed=416A789C31C5E8C1 -Dtests.security.manager=true -Dtests.locale=bs-Cyrl-BA -Dtests.timezone=America/Guadeloupe -Dcompiler.java=12 -Druntime.java=11
  2> java.lang.AssertionError: Not all logs matched. Unmatched logs:
    {node.id=Xxg8JBmdT0qBIqPgG5J9Ww, origin.type=local_node, user.name=_system, type=audit, user.realm=__fallback, request.id=T1yUUxPoT5a3Y6a641CLmA, event.action=access_denied, indices=[.enrich-*], request.name=GetIndexRequest, origin.address=127.0.0.1:33817, event.type=transport, action=indices:admin/get, timestamp=2019-10-16T06:52:07,688+0000, user.roles=[_system]}

That's from https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+multijob-unix-compatibility/os=debian-9&&immutable/329/consoleText

The REPRO command is:

./gradlew ':x-pack:plugin:sql:qa:security:with-ssl:integTestRunner' --tests "org.elasticsearch.xpack.sql.qa.security.CliSecurityIT.testDescribeWorksAsFullAccess" \
  -Dtests.seed=416A789C31C5E8C1 \
  -Dtests.security.manager=true \
  -Dtests.locale=bs-Cyrl-BA \
  -Dtests.timezone=America/Guadeloupe \
  -Dcompiler.java=12 \
  -Druntime.java=11

This did not reproduce locally for me.

[elasticmachine]

Pinging @elastic/es-search (:Search/SQL)

[droberts195]

A similar thing just happened in https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+multijob-unix-compatibility/os=fedora-29&&immutable/331/consoleText, but with the first failure in CliSecurityIT.testDescribeWorksAsAdmin:

org.elasticsearch.xpack.sql.qa.security.CliSecurityIT > testDescribeWorksAsAdmin FAILED
    java.lang.AssertionError: Not all logs matched. Unmatched logs:
    {node.id=BJdMYjtfSFuMQ2iRWRU7ZQ, origin.type=local_node, user.name=_system, type=audit, user.realm=__fallback, request.id=0jizkzmWSMu_hiIUMokTow, event.action=access_denied, indices=[.enrich-*], request.name=GetIndexRequest, origin.address=127.0.0.1:38837, event.type=transport, action=indices:admin/get, timestamp=2019-10-16T14:47:41,446+0000, user.roles=[_system]}
REPRODUCE WITH: ./gradlew ':x-pack:plugin:sql:qa:security:with-ssl:integTestRunner' --tests "org.elasticsearch.xpack.sql.qa.security.CliSecurityIT.testDescribeWorksAsAdmin" -Dtests.seed=175A48A4015214B5 -Dtests.security.manager=true -Dtests.locale=mr -Dtests.timezone=Pacific/Auckland -Dcompiler.java=12 -Druntime.java=11

org.elasticsearch.xpack.sql.qa.security.CliSecurityIT > testDescribeWithNoAccess FAILED
    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.
REPRODUCE WITH: ./gradlew ':x-pack:plugin:sql:qa:security:with-ssl:integTestRunner' --tests "org.elasticsearch.xpack.sql.qa.security.CliSecurityIT.testDescribeWithNoAccess" -Dtests.seed=175A48A4015214B5 -Dtests.security.manager=true -Dtests.locale=mr -Dtests.timezone=Pacific/Auckland -Dcompiler.java=12 -Druntime.java=11

org.elasticsearch.xpack.sql.qa.security.CliSecurityIT > testQueryStringSingleFieldGrantedWrongRequested FAILED
    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.
REPRODUCE WITH: ./gradlew ':x-pack:plugin:sql:qa:security:with-ssl:integTestRunner' --tests "org.elasticsearch.xpack.sql.qa.security.CliSecurityIT.testQueryStringSingleFieldGrantedWrongRequested" -Dtests.seed=175A48A4015214B5 -Dtests.security.manager=true -Dtests.locale=mr -Dtests.timezone=Pacific/Auckland -Dcompiler.java=12 -Druntime.java=11

org.elasticsearch.xpack.sql.qa.security.CliSecurityIT > testShowTablesWithNoAccess FAILED
    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.
REPRODUCE WITH: ./gradlew ':x-pack:plugin:sql:qa:security:with-ssl:integTestRunner' --tests "org.elasticsearch.xpack.sql.qa.security.CliSecurityIT.testShowTablesWithNoAccess" -Dtests.seed=175A48A4015214B5 -Dtests.security.manager=true -Dtests.locale=mr -Dtests.timezone=Pacific/Auckland -Dcompiler.java=12 -Druntime.java=11

org.elasticsearch.xpack.sql.qa.security.CliSecurityIT > testQuerySingleFieldExcepted FAILED
    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.
REPRODUCE WITH: ./gradlew ':x-pack:plugin:sql:qa:security:with-ssl:integTestRunner' --tests "org.elasticsearch.xpack.sql.qa.security.CliSecurityIT.testQuerySingleFieldExcepted" -Dtests.seed=175A48A4015214B5 -Dtests.security.manager=true -Dtests.locale=mr -Dtests.timezone=Pacific/Auckland -Dcompiler.java=12 -Druntime.java=11

Also in https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+multijob-unix-compatibility/os=opensuse-42-3&&immutable/331/consoleText, but with the first failure in JdbcSecurityIT.testShowTablesWorksAsFullAccess:

org.elasticsearch.xpack.sql.qa.security.JdbcSecurityIT > testShowTablesWorksAsFullAccess FAILED
    java.lang.AssertionError: Not all logs matched. Unmatched logs:
    {node.id=r2dkCn6YQxuQmWolA1lplw, origin.type=local_node, user.name=_system, type=audit, user.realm=__fallback, request.id=jDTBCEbSTE2TNDw05C2XYA, event.action=access_denied, indices=[.enrich-*], request.name=GetIndexRequest, origin.address=127.0.0.1:43094, event.type=transport, action=indices:admin/get, timestamp=2019-10-16T14:48:20,977+0000, user.roles=[_system]}
REPRODUCE WITH: ./gradlew ':x-pack:plugin:sql:qa:security:with-ssl:integTestRunner' --tests "org.elasticsearch.xpack.sql.qa.security.JdbcSecurityIT.testShowTablesWorksAsFullAccess" -Dtests.seed=7E72C9E408941EA4 -Dtests.security.manager=true -Dtests.locale=hi-IN -Dtests.timezone=Australia/Lindeman -Dcompiler.java=12 -Druntime.java=11

org.elasticsearch.xpack.sql.qa.security.JdbcSecurityIT > testScrollWithSingleFieldExcepted FAILED
    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.
REPRODUCE WITH: ./gradlew ':x-pack:plugin:sql:qa:security:with-ssl:integTestRunner' --tests "org.elasticsearch.xpack.sql.qa.security.JdbcSecurityIT.testScrollWithSingleFieldExcepted" -Dtests.seed=7E72C9E408941EA4 -Dtests.security.manager=true -Dtests.locale=hi-IN -Dtests.timezone=Australia/Lindeman -Dcompiler.java=12 -Druntime.java=11

So it seems that to silence this class of failure the entirety of both CliSecurityIT and JdbcSecurityIT would need to be muted. What do you think @matriv?

[mark-vieira]

There are a number of these builds that fail with assertion errors in basically the entire CliSecurityIT suite. There doesn't seem to be a consistent pattern in terms of job configuration or platform.

https://gradle-enterprise.elastic.co/s/h5t5objanvhpk/tests/failed
https://gradle-enterprise.elastic.co/s/6tzhbqmzbfpaq/tests/failed
https://gradle-enterprise.elastic.co/s/6fxzvikol63cu/tests/failed
https://gradle-enterprise.elastic.co/s/677gidbftg3hy/tests/failed
https://gradle-enterprise.elastic.co/s/dtjepark7fozu/tests/failed
https://gradle-enterprise.elastic.co/s/4pmzwlh5zshgq/tests/failed
https://gradle-enterprise.elastic.co/s/5hg5j2537sdnm/tests/failed
https://gradle-enterprise.elastic.co/s/qljxa73qplxbo/tests/failed

[astefan]

It seems that all these failures have to do with an audit log that involves the newly added enrich processor index... and the timing seems to match as well.

[mark-vieira]

@elastic/es-core-features ☝️thoughts?

[alpar-t]

this led to even more failures, I muted the suite in a340795

[mark-vieira]

this led to even more failures, I muted the suite in a340795

This is failing in 7.x as well. Should we mute there too?

[astefan]

#48098 might be related

[alpar-t]

Muted in 7.x too fe265f0

[iverase]

I am muting 7.5 as well

[astefan]

@jbaiera could #48098 be the fix for these failures here? What happens with sql tests in this specific issue is that some unexpected audit log entry resembling {node.id=r2dkCn6YQxuQmWolA1lplw, origin.type=local_node, user.name=_system, type=audit, user.realm=__fallback, request.id=jDTBCEbSTE2TNDw05C2XYA, event.action=access_denied, indices=[.enrich-*], request.name=GetIndexRequest, origin.address=127.0.0.1:43094, event.type=transport, action=indices:admin/get, timestamp=2019-10-16T14:48:20,977+0000, user.roles=[_system]} is messing up the expectation. These seem to have been showing up first almost a week ago.

[jbaiera]

I think the reason for that log line was that the background maintenance task for enrich was failing when running with security. The authentication failure was making it to the audit log. Now that it's fixed, the log message should be gone

[matriv]

Re-enabled:
master : 4703623
7.x : 124f6d0
7.5 : 1051342

Many thanks @jbaiera and @astefan for chasing this!