Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

ApiKeyIntegTests#testGetAndInvalidateApiKeysWithExpiredAndInvalidatedApiKey is failing #38408

Closed
jasontedor opened this issue Feb 5, 2019 · 5 comments
Closed

ApiKeyIntegTests#testGetAndInvalidateApiKeysWithExpiredAndInvalidatedApiKey is failing #38408

jasontedor opened this issue Feb 5, 2019 · 5 comments
Assignees
@bizybot
Labels
:Security/Authentication Logging in, Usernames/passwords, Realms (Native/LDAP/AD/SAML/PKI/etc) >test-failure Triaged test failures from CI

Comments

@jasontedor
Copy link
Member

This test failed on my [PR build]. The reproduction line is:

05:17:22    2> REPRODUCE WITH: ./gradlew :x-pack:plugin:security:unitTest -Dtests.seed=D84FAE5E21AE11F0 -Dtests.class=org.elasticsearch.xpack.security.authc.ApiKeyIntegTests -Dtests.method="testGetAndInvalidateApiKeysWithExpiredAndInvalidatedApiKey" -Dtests.security.manager=true -Dtests.locale=es-GT -Dtests.timezone=America/Boise -Dcompiler.java=11 -Druntime.java=8

Here are some logs:

05:17:22    1> [2019-02-05T03:17:13,251][INFO ][o.e.x.s.a.ApiKeyIntegTests] [testGetAndInvalidateApiKeysWithExpiredAndInvalidatedApiKey] before test
05:17:22    1> [2019-02-05T03:17:13,251][INFO ][o.e.x.s.a.ApiKeyIntegTests] [testGetAndInvalidateApiKeysWithExpiredAndInvalidatedApiKey] [ApiKeyIntegTests#testGetAndInvalidateApiKeysWithExpiredAndInvalidatedApiKey]: setting up test
05:17:22    1> [2019-02-05T03:17:13,262][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sm1] action="cluster:monitor/nodes/liveness" event.action="access_granted" event.type="transport" origin.address="127.0.0.1:47336" origin.type="transport" request.id="8vfpOGzNSbaSlgyMNIYKtw" request.name="LivenessRequest" user.name="test_trans_client_user" user.realm="file" user.roles="["transport_client","user"]"
05:17:22    1> [2019-02-05T03:17:13,265][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sc6] action="indices:admin/delete" event.action="access_granted" event.type="transport" host.ip="127.0.0.1" host.name="127.0.0.1" indices="["*","-*"]" node.id="yCxkPJjtTryFjOKuvn-d-A" node.name="node_sc6" origin.address="127.0.0.1:38398" origin.type="transport" request.id="IKekdxmqSWKLhIG7skdfyQ" request.name="DeleteIndexRequest" user.name="test_trans_client_user" user.realm="file" user.roles="["transport_client","user"]"
05:17:22    1> [2019-02-05T03:17:13,265][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sc6] action="indices:admin/delete" event.action="access_granted" event.type="transport" host.ip="127.0.0.1" host.name="127.0.0.1" indices="["*","-*"]" node.id="yCxkPJjtTryFjOKuvn-d-A" node.name="node_sc6" origin.address="127.0.0.1:38398" origin.type="transport" request.id="IKekdxmqSWKLhIG7skdfyQ" request.name="DeleteIndexRequest" user.name="test_trans_client_user" user.realm="file" user.roles="["transport_client","user"]"
05:17:22    1> [2019-02-05T03:17:13,274][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sc6] action="indices:admin/template/put" event.action="access_granted" event.type="transport" host.ip="127.0.0.1" host.name="127.0.0.1" indices="["*"]" node.id="yCxkPJjtTryFjOKuvn-d-A" node.name="node_sc6" origin.address="127.0.0.1:38400" origin.type="transport" request.id="JYMRBd9tRqWv2kTADv9YPA" request.name="PutIndexTemplateRequest" user.name="test_trans_client_user" user.realm="file" user.roles="["transport_client","user"]"
05:17:22    1> [2019-02-05T03:17:13,274][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sc6] action="indices:admin/template/put" event.action="access_granted" event.type="transport" host.ip="127.0.0.1" host.name="127.0.0.1" indices="["*"]" node.id="yCxkPJjtTryFjOKuvn-d-A" node.name="node_sc6" origin.address="127.0.0.1:38400" origin.type="transport" request.id="JYMRBd9tRqWv2kTADv9YPA" request.name="PutIndexTemplateRequest" user.name="test_trans_client_user" user.realm="file" user.roles="["transport_client","user"]"
05:17:22    1> [2019-02-05T03:17:13,277][INFO ][o.e.c.m.MetaDataIndexTemplateService] [node_sm0] adding template [random_index_template] for index patterns [*]
05:17:22    1> [2019-02-05T03:17:13,299][INFO ][o.e.x.s.a.ApiKeyIntegTests] [testGetAndInvalidateApiKeysWithExpiredAndInvalidatedApiKey] [ApiKeyIntegTests#testGetAndInvalidateApiKeysWithExpiredAndInvalidatedApiKey]: all set up test
05:17:22    1> [2019-02-05T03:17:13,300][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sc6] action="cluster:monitor/nodes/info" event.action="access_granted" event.type="transport" host.ip="127.0.0.1" host.name="127.0.0.1" node.id="yCxkPJjtTryFjOKuvn-d-A" node.name="node_sc6" origin.address="127.0.0.1:38402" origin.type="transport" request.id="J41YgF6HRzuv-fNsQAN2EQ" request.name="NodesInfoRequest" user.name="test_trans_client_user" user.realm="file" user.roles="["transport_client","user"]"
05:17:22    1> [2019-02-05T03:17:13,300][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sc6] action="cluster:monitor/nodes/info" event.action="access_granted" event.type="transport" host.ip="127.0.0.1" host.name="127.0.0.1" node.id="yCxkPJjtTryFjOKuvn-d-A" node.name="node_sc6" origin.address="127.0.0.1:38402" origin.type="transport" request.id="J41YgF6HRzuv-fNsQAN2EQ" request.name="NodesInfoRequest" user.name="test_trans_client_user" user.realm="file" user.roles="["transport_client","user"]"
05:17:22    1> [2019-02-05T03:17:13,300][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sc6] action="cluster:monitor/nodes/info[n]" event.action="access_granted" event.type="transport" host.ip="127.0.0.1" host.name="127.0.0.1" node.id="yCxkPJjtTryFjOKuvn-d-A" node.name="node_sc6" origin.address="127.0.0.1:40373" origin.type="local_node" request.id="J41YgF6HRzuv-fNsQAN2EQ" request.name="NodeInfoRequest" user.name="test_trans_client_user" user.realm="file" user.roles="["transport_client","user"]"
05:17:22    1> [2019-02-05T03:17:13,301][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sm1] action="cluster:monitor/nodes/info[n]" event.action="access_granted" event.type="transport" origin.address="127.0.0.1:35280" origin.type="transport" request.id="J41YgF6HRzuv-fNsQAN2EQ" request.name="NodeInfoRequest" user.name="test_trans_client_user" user.realm="file" user.roles="["transport_client","user"]"
05:17:22    1> [2019-02-05T03:17:13,377][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sc6] action="cluster:monitor/state" event.action="access_granted" event.type="transport" host.ip="127.0.0.1" host.name="127.0.0.1" indices="[]" node.id="yCxkPJjtTryFjOKuvn-d-A" node.name="node_sc6" origin.address="127.0.0.1:38404" origin.type="transport" request.id="5TrULZfDSJGHN-Jvq9QUHw" request.name="ClusterStateRequest" user.name="test_trans_client_user" user.realm="file" user.roles="["transport_client","user"]"
05:17:22    1> [2019-02-05T03:17:13,378][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sc6] action="cluster:monitor/state" event.action="access_granted" event.type="transport" host.ip="127.0.0.1" host.name="127.0.0.1" indices="[]" node.id="yCxkPJjtTryFjOKuvn-d-A" node.name="node_sc6" origin.address="127.0.0.1:38404" origin.type="transport" request.id="5TrULZfDSJGHN-Jvq9QUHw" request.name="ClusterStateRequest" user.name="test_trans_client_user" user.realm="file" user.roles="["transport_client","user"]"
05:17:22    1> [2019-02-05T03:17:13,469][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sm1] action="cluster:monitor/state" event.action="access_granted" event.type="transport" indices="[]" origin.address="127.0.0.1:36016" origin.type="transport" request.id="gG-TqB2rTSWNJampsC_GYQ" request.name="ClusterStateRequest" user.name="test_trans_client_user" user.realm="file" user.roles="["transport_client","user"]"
05:17:22    1> [2019-02-05T03:17:13,469][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sm1] action="cluster:monitor/state" event.action="access_granted" event.type="transport" indices="[]" origin.address="127.0.0.1:36016" origin.type="transport" request.id="gG-TqB2rTSWNJampsC_GYQ" request.name="ClusterStateRequest" user.name="test_trans_client_user" user.realm="file" user.roles="["transport_client","user"]"
05:17:22    1> [2019-02-05T03:17:13,689][INFO ][o.e.c.m.MetaDataCreateIndexService] [node_sm0] [.security-6] creating index, cause [api], templates [random_index_template], shards [1]/[0], mappings [doc]
05:17:22    1> [2019-02-05T03:17:13,689][INFO ][o.e.c.r.a.AllocationService] [node_sm0] updating number_of_replicas to [1] for indices [.security-6]
05:17:22    1> [2019-02-05T03:17:13,713][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sm1] action="cluster:admin/xpack/security/realm/cache/clear[n]" event.action="access_granted" event.type="transport" origin.address="127.0.0.1:35346" origin.type="transport" request.id="wJ8H2gPmRLitONf82Sxg7Q" request.name="Node" user.name="_xpack_security" user.realm="__attach" user.roles="["superuser"]"
05:17:22    1> [2019-02-05T03:17:13,714][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sc6] action="cluster:admin/xpack/security/realm/cache/clear[n]" event.action="access_granted" event.type="transport" host.ip="127.0.0.1" host.name="127.0.0.1" node.id="yCxkPJjtTryFjOKuvn-d-A" node.name="node_sc6" origin.address="127.0.0.1:38224" origin.type="transport" request.id="wJ8H2gPmRLitONf82Sxg7Q" request.name="Node" user.name="_xpack_security" user.realm="__attach" user.roles="["superuser"]"
05:17:22    1> [2019-02-05T03:17:13,714][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sm1] action="cluster:admin/xpack/security/realm/cache/clear" event.action="access_granted" event.type="transport" origin.address="127.0.0.1:39965" origin.type="local_node" request.id="qaDccyxyTvGmVDSw7EiRqw" request.name="ClearRealmCacheRequest" user.name="_xpack_security" user.realm="__attach" user.roles="["superuser"]"
05:17:22    1> [2019-02-05T03:17:13,716][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sc6] action="cluster:admin/xpack/security/realm/cache/clear[n]" event.action="access_granted" event.type="transport" host.ip="127.0.0.1" host.name="127.0.0.1" node.id="yCxkPJjtTryFjOKuvn-d-A" node.name="node_sc6" origin.address="127.0.0.1:38006" origin.type="transport" request.id="FTizYvvpRDOY4UF8YekK0Q" request.name="Node" user.name="_xpack_security" user.realm="__attach" user.roles="["superuser"]"
05:17:22    1> [2019-02-05T03:17:13,716][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sc6] action="cluster:admin/xpack/security/realm/cache/clear[n]" event.action="access_granted" event.type="transport" host.ip="127.0.0.1" host.name="127.0.0.1" node.id="yCxkPJjtTryFjOKuvn-d-A" node.name="node_sc6" origin.address="127.0.0.1:37940" origin.type="transport" request.id="qaDccyxyTvGmVDSw7EiRqw" request.name="Node" user.name="_xpack_security" user.realm="__attach" user.roles="["superuser"]"
05:17:22    1> [2019-02-05T03:17:13,716][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sm1] action="cluster:admin/xpack/security/realm/cache/clear[n]" event.action="access_granted" event.type="transport" origin.address="127.0.0.1:39965" origin.type="local_node" request.id="qaDccyxyTvGmVDSw7EiRqw" request.name="Node" user.name="_xpack_security" user.realm="__attach" user.roles="["superuser"]"
05:17:22    1> [2019-02-05T03:17:13,717][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sc6] action="cluster:admin/xpack/security/realm/cache/clear" event.action="access_granted" event.type="transport" host.ip="127.0.0.1" host.name="127.0.0.1" node.id="yCxkPJjtTryFjOKuvn-d-A" node.name="node_sc6" origin.address="127.0.0.1:40373" origin.type="local_node" request.id="D8CKn1aNRkaMWnDTjjKhhA" request.name="ClearRealmCacheRequest" user.name="_xpack_security" user.realm="__attach" user.roles="["superuser"]"
05:17:22    1> [2019-02-05T03:17:13,717][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sm1] action="cluster:admin/xpack/security/realm/cache/clear[n]" event.action="access_granted" event.type="transport" origin.address="127.0.0.1:35180" origin.type="transport" request.id="FTizYvvpRDOY4UF8YekK0Q" request.name="Node" user.name="_xpack_security" user.realm="__attach" user.roles="["superuser"]"
05:17:22    1> [2019-02-05T03:17:13,718][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sm1] action="cluster:admin/xpack/security/realm/cache/clear[n]" event.action="access_granted" event.type="transport" origin.address="127.0.0.1:35288" origin.type="transport" request.id="D8CKn1aNRkaMWnDTjjKhhA" request.name="Node" user.name="_xpack_security" user.realm="__attach" user.roles="["superuser"]"
05:17:22    1> [2019-02-05T03:17:13,720][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sc6] action="cluster:admin/xpack/security/realm/cache/clear[n]" event.action="access_granted" event.type="transport" host.ip="127.0.0.1" host.name="127.0.0.1" node.id="yCxkPJjtTryFjOKuvn-d-A" node.name="node_sc6" origin.address="127.0.0.1:40373" origin.type="local_node" request.id="D8CKn1aNRkaMWnDTjjKhhA" request.name="Node" user.name="_xpack_security" user.realm="__attach" user.roles="["superuser"]"
05:17:22    1> [2019-02-05T03:17:13,721][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sm1] action="cluster:admin/xpack/security/realm/cache/clear[n]" event.action="access_granted" event.type="transport" origin.address="127.0.0.1:35160" origin.type="transport" request.id="oDMDWmf1RYWbdar2T9Lp1Q" request.name="Node" user.name="_xpack_security" user.realm="__attach" user.roles="["superuser"]"
05:17:22    1> [2019-02-05T03:17:13,721][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sc6] action="cluster:admin/xpack/security/realm/cache/clear[n]" event.action="access_granted" event.type="transport" host.ip="127.0.0.1" host.name="127.0.0.1" node.id="yCxkPJjtTryFjOKuvn-d-A" node.name="node_sc6" origin.address="127.0.0.1:38100" origin.type="transport" request.id="oDMDWmf1RYWbdar2T9Lp1Q" request.name="Node" user.name="_xpack_security" user.realm="__attach" user.roles="["superuser"]"
05:17:22    1> [2019-02-05T03:17:13,743][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sc6] action="cluster:admin/xpack/security/realm/cache/clear[n]" event.action="access_granted" event.type="transport" host.ip="127.0.0.1" host.name="127.0.0.1" node.id="yCxkPJjtTryFjOKuvn-d-A" node.name="node_sc6" origin.address="127.0.0.1:38318" origin.type="transport" request.id="EJrVpjo0SnWt6WMk2oChwA" request.name="Node" user.name="_xpack_security" user.realm="__attach" user.roles="["superuser"]"
05:17:22    1> [2019-02-05T03:17:13,743][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sm1] action="cluster:admin/xpack/security/realm/cache/clear[n]" event.action="access_granted" event.type="transport" origin.address="127.0.0.1:35318" origin.type="transport" request.id="EJrVpjo0SnWt6WMk2oChwA" request.name="Node" user.name="_xpack_security" user.realm="__attach" user.roles="["superuser"]"
05:17:22    1> [2019-02-05T03:17:13,763][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sm1] action="cluster:admin/xpack/security/realm/cache/clear[n]" event.action="access_granted" event.type="transport" origin.address="127.0.0.1:35216" origin.type="transport" request.id="83AcT2a1S6W3Nk5heXTc6g" request.name="Node" user.name="_xpack_security" user.realm="__attach" user.roles="["superuser"]"
05:17:22    1> [2019-02-05T03:17:13,767][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sc6] action="cluster:admin/xpack/security/realm/cache/clear[n]" event.action="access_granted" event.type="transport" host.ip="127.0.0.1" host.name="127.0.0.1" node.id="yCxkPJjtTryFjOKuvn-d-A" node.name="node_sc6" origin.address="127.0.0.1:37926" origin.type="transport" request.id="83AcT2a1S6W3Nk5heXTc6g" request.name="Node" user.name="_xpack_security" user.realm="__attach" user.roles="["superuser"]"
05:17:22    1> [2019-02-05T03:17:13,853][INFO ][o.e.c.r.a.AllocationService] [node_sm0] Cluster health status changed from [YELLOW] to [GREEN] (reason: [shards started [[.security-6][0]] ...]).
05:17:22    1> [2019-02-05T03:17:14,067][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sc6] action="cluster:monitor/nodes/liveness" event.action="access_granted" event.type="transport" host.ip="127.0.0.1" host.name="127.0.0.1" node.id="yCxkPJjtTryFjOKuvn-d-A" node.name="node_sc6" origin.address="127.0.0.1:50076" origin.type="transport" request.id="awlsePjsRh6JYOSnDowkmw" request.name="LivenessRequest" user.name="test_trans_client_user" user.realm="file" user.roles="["transport_client","user"]"
05:17:22    1> [2019-02-05T03:17:14,334][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sm1] action="cluster:monitor/nodes/liveness" event.action="access_granted" event.type="transport" origin.address="127.0.0.1:47686" origin.type="transport" request.id="nniQNuG4Smqd3qssDvgvlw" request.name="LivenessRequest" user.name="test_trans_client_user" user.realm="file" user.roles="["transport_client","user"]"
05:17:22    1> [2019-02-05T03:17:15,074][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sc6] action="cluster:monitor/nodes/liveness" event.action="access_granted" event.type="transport" host.ip="127.0.0.1" host.name="127.0.0.1" node.id="yCxkPJjtTryFjOKuvn-d-A" node.name="node_sc6" origin.address="127.0.0.1:50444" origin.type="transport" request.id="oYXL7SybRjui-2yqcvLhwQ" request.name="LivenessRequest" user.name="test_trans_client_user" user.realm="file" user.roles="["transport_client","user"]"
05:17:22    1> [2019-02-05T03:17:15,133][INFO ][o.e.c.m.MetaDataDeleteIndexService] [node_sm0] [.security-6/vbuoEL2pT72weFdTR28x0Q] deleting index
05:17:22    1> [2019-02-05T03:17:15,144][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sc6] action="cluster:admin/xpack/security/realm/cache/clear" event.action="access_granted" event.type="transport" host.ip="127.0.0.1" host.name="127.0.0.1" node.id="yCxkPJjtTryFjOKuvn-d-A" node.name="node_sc6" origin.address="127.0.0.1:40373" origin.type="local_node" request.id="VYU_AsQ6ShS7-8-1dhts8w" request.name="ClearRealmCacheRequest" user.name="_xpack_security" user.realm="__attach" user.roles="["superuser"]"
05:17:22    1> [2019-02-05T03:17:15,145][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sm1] action="cluster:admin/xpack/security/realm/cache/clear" event.action="access_granted" event.type="transport" origin.address="127.0.0.1:39965" origin.type="local_node" request.id="bjFxNzf8TiaXo1NpkwUjVQ" request.name="ClearRealmCacheRequest" user.name="_xpack_security" user.realm="__attach" user.roles="["superuser"]"
05:17:22    1> [2019-02-05T03:17:15,145][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sc6] action="cluster:admin/xpack/security/realm/cache/clear[n]" event.action="access_granted" event.type="transport" host.ip="127.0.0.1" host.name="127.0.0.1" node.id="yCxkPJjtTryFjOKuvn-d-A" node.name="node_sc6" origin.address="127.0.0.1:40373" origin.type="local_node" request.id="VYU_AsQ6ShS7-8-1dhts8w" request.name="Node" user.name="_xpack_security" user.realm="__attach" user.roles="["superuser"]"
05:17:22    1> [2019-02-05T03:17:15,146][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sm1] action="cluster:admin/xpack/security/realm/cache/clear[n]" event.action="access_granted" event.type="transport" origin.address="127.0.0.1:39965" origin.type="local_node" request.id="bjFxNzf8TiaXo1NpkwUjVQ" request.name="Node" user.name="_xpack_security" user.realm="__attach" user.roles="["superuser"]"
05:17:22    1> [2019-02-05T03:17:15,147][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sc6] action="cluster:admin/xpack/security/realm/cache/clear[n]" event.action="access_granted" event.type="transport" host.ip="127.0.0.1" host.name="127.0.0.1" node.id="yCxkPJjtTryFjOKuvn-d-A" node.name="node_sc6" origin.address="127.0.0.1:37940" origin.type="transport" request.id="bjFxNzf8TiaXo1NpkwUjVQ" request.name="Node" user.name="_xpack_security" user.realm="__attach" user.roles="["superuser"]"
05:17:22    1> [2019-02-05T03:17:15,151][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sm1] action="cluster:admin/xpack/security/realm/cache/clear[n]" event.action="access_granted" event.type="transport" origin.address="127.0.0.1:35280" origin.type="transport" request.id="VYU_AsQ6ShS7-8-1dhts8w" request.name="Node" user.name="_xpack_security" user.realm="__attach" user.roles="["superuser"]"
05:17:22    1> [2019-02-05T03:17:15,151][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sm1] action="cluster:admin/xpack/security/realm/cache/clear[n]" event.action="access_granted" event.type="transport" origin.address="127.0.0.1:35180" origin.type="transport" request.id="tGBILR6YTn268uprSMgq4w" request.name="Node" user.name="_xpack_security" user.realm="__attach" user.roles="["superuser"]"
05:17:22    1> [2019-02-05T03:17:15,152][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sc6] action="cluster:admin/xpack/security/realm/cache/clear[n]" event.action="access_granted" event.type="transport" host.ip="127.0.0.1" host.name="127.0.0.1" node.id="yCxkPJjtTryFjOKuvn-d-A" node.name="node_sc6" origin.address="127.0.0.1:38006" origin.type="transport" request.id="tGBILR6YTn268uprSMgq4w" request.name="Node" user.name="_xpack_security" user.realm="__attach" user.roles="["superuser"]"
05:17:22    1> [2019-02-05T03:17:15,160][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sm1] action="cluster:admin/xpack/security/realm/cache/clear[n]" event.action="access_granted" event.type="transport" origin.address="127.0.0.1:35160" origin.type="transport" request.id="zfSVabD1SrG5mUu6iFYyrw" request.name="Node" user.name="_xpack_security" user.realm="__attach" user.roles="["superuser"]"
05:17:22    1> [2019-02-05T03:17:15,160][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sc6] action="cluster:admin/xpack/security/realm/cache/clear[n]" event.action="access_granted" event.type="transport" host.ip="127.0.0.1" host.name="127.0.0.1" node.id="yCxkPJjtTryFjOKuvn-d-A" node.name="node_sc6" origin.address="127.0.0.1:38100" origin.type="transport" request.id="zfSVabD1SrG5mUu6iFYyrw" request.name="Node" user.name="_xpack_security" user.realm="__attach" user.roles="["superuser"]"
05:17:22    1> [2019-02-05T03:17:15,163][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sc6] action="cluster:admin/xpack/security/realm/cache/clear[n]" event.action="access_granted" event.type="transport" host.ip="127.0.0.1" host.name="127.0.0.1" node.id="yCxkPJjtTryFjOKuvn-d-A" node.name="node_sc6" origin.address="127.0.0.1:38318" origin.type="transport" request.id="ndN_SKbySCi9cvoqaT3WJw" request.name="Node" user.name="_xpack_security" user.realm="__attach" user.roles="["superuser"]"
05:17:22    1> [2019-02-05T03:17:15,164][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sm1] action="cluster:admin/xpack/security/realm/cache/clear[n]" event.action="access_granted" event.type="transport" origin.address="127.0.0.1:35318" origin.type="transport" request.id="ndN_SKbySCi9cvoqaT3WJw" request.name="Node" user.name="_xpack_security" user.realm="__attach" user.roles="["superuser"]"
05:17:22    1> [2019-02-05T03:17:15,169][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sc6] action="cluster:admin/xpack/security/realm/cache/clear[n]" event.action="access_granted" event.type="transport" host.ip="127.0.0.1" host.name="127.0.0.1" node.id="yCxkPJjtTryFjOKuvn-d-A" node.name="node_sc6" origin.address="127.0.0.1:38216" origin.type="transport" request.id="94EHdriEQWaufxIw7xjObw" request.name="Node" user.name="_xpack_security" user.realm="__attach" user.roles="["superuser"]"
05:17:22    1> [2019-02-05T03:17:15,169][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sm1] action="cluster:admin/xpack/security/realm/cache/clear[n]" event.action="access_granted" event.type="transport" origin.address="127.0.0.1:35338" origin.type="transport" request.id="94EHdriEQWaufxIw7xjObw" request.name="Node" user.name="_xpack_security" user.realm="__attach" user.roles="["superuser"]"
05:17:22    1> [2019-02-05T03:17:15,180][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sc6] action="cluster:admin/xpack/security/realm/cache/clear[n]" event.action="access_granted" event.type="transport" host.ip="127.0.0.1" host.name="127.0.0.1" node.id="yCxkPJjtTryFjOKuvn-d-A" node.name="node_sc6" origin.address="127.0.0.1:37922" origin.type="transport" request.id="WimfARS8RmmI7eTGi-gBFQ" request.name="Node" user.name="_xpack_security" user.realm="__attach" user.roles="["superuser"]"
05:17:22    1> [2019-02-05T03:17:15,181][INFO ][o.e.x.s.a.ApiKeyIntegTests] [testGetAndInvalidateApiKeysWithExpiredAndInvalidatedApiKey] [ApiKeyIntegTests#testGetAndInvalidateApiKeysWithExpiredAndInvalidatedApiKey]: cleaning up after test
05:17:22    1> [2019-02-05T03:17:15,186][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sm1] action="cluster:admin/xpack/security/realm/cache/clear[n]" event.action="access_granted" event.type="transport" origin.address="127.0.0.1:35210" origin.type="transport" request.id="WimfARS8RmmI7eTGi-gBFQ" request.name="Node" user.name="_xpack_security" user.realm="__attach" user.roles="["superuser"]"
05:17:22    1> [2019-02-05T03:17:15,300][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sc6] action="cluster:monitor/health" event.action="access_granted" event.type="transport" host.ip="127.0.0.1" host.name="127.0.0.1" indices="[]" node.id="yCxkPJjtTryFjOKuvn-d-A" node.name="node_sc6" origin.address="127.0.0.1:38406" origin.type="transport" request.id="wHuqWeTXT6a0P09VsPqkdg" request.name="ClusterHealthRequest" user.name="test_trans_client_user" user.realm="file" user.roles="["transport_client","user"]"
05:17:22    1> [2019-02-05T03:17:15,300][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sc6] action="cluster:monitor/health" event.action="access_granted" event.type="transport" host.ip="127.0.0.1" host.name="127.0.0.1" indices="[]" node.id="yCxkPJjtTryFjOKuvn-d-A" node.name="node_sc6" origin.address="127.0.0.1:38406" origin.type="transport" request.id="wHuqWeTXT6a0P09VsPqkdg" request.name="ClusterHealthRequest" user.name="test_trans_client_user" user.realm="file" user.roles="["transport_client","user"]"
05:17:22    1> [2019-02-05T03:17:15,367][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sc6] action="cluster:monitor/state" event.action="access_granted" event.type="transport" host.ip="127.0.0.1" host.name="127.0.0.1" indices="[]" node.id="yCxkPJjtTryFjOKuvn-d-A" node.name="node_sc6" origin.address="127.0.0.1:38408" origin.type="transport" request.id="ZsXLndPcTfa99k6bmTzIeQ" request.name="ClusterStateRequest" user.name="test_trans_client_user" user.realm="file" user.roles="["transport_client","user"]"
05:17:22    1> [2019-02-05T03:17:15,367][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sc6] action="cluster:monitor/state" event.action="access_granted" event.type="transport" host.ip="127.0.0.1" host.name="127.0.0.1" indices="[]" node.id="yCxkPJjtTryFjOKuvn-d-A" node.name="node_sc6" origin.address="127.0.0.1:38408" origin.type="transport" request.id="ZsXLndPcTfa99k6bmTzIeQ" request.name="ClusterStateRequest" user.name="test_trans_client_user" user.realm="file" user.roles="["transport_client","user"]"
05:17:22    1> [2019-02-05T03:17:15,419][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sm1] action="cluster:monitor/nodes/liveness" event.action="access_granted" event.type="transport" origin.address="127.0.0.1:48158" origin.type="transport" request.id="gBMRGW0lTxiozC3s7e77bw" request.name="LivenessRequest" user.name="test_trans_client_user" user.realm="file" user.roles="["transport_client","user"]"
05:17:22    1> [2019-02-05T03:17:15,681][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [testGetAndInvalidateApiKeysWithExpiredAndInvalidatedApiKey] action="cluster:monitor/state" event.action="access_granted" event.type="transport" indices="[]" origin.address="127.0.0.1:39965" origin.type="local_node" request.id="V01OGnZRQ1O4fXoyQU6QVg" request.name="ClusterStateRequest" user.name="test_user" user.realm="file" user.roles="["user"]"
05:17:22    1> [2019-02-05T03:17:15,791][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sm1] action="indices:admin/template/delete" event.action="access_granted" event.type="transport" origin.address="127.0.0.1:36018" origin.type="transport" request.id="qHKReoZ7Tii2A2bIXNETqA" request.name="DeleteIndexTemplateRequest" user.name="test_trans_client_user" user.realm="file" user.roles="["transport_client","user"]"
05:17:22    1> [2019-02-05T03:17:15,791][INFO ][o.e.x.s.a.l.LoggingAuditTrail] [node_sm1] action="indices:admin/template/delete" event.action="access_granted" event.type="transport" origin.address="127.0.0.1:36018" origin.type="transport" request.id="qHKReoZ7Tii2A2bIXNETqA" request.name="DeleteIndexTemplateRequest" user.name="test_trans_client_user" user.realm="file" user.roles="["transport_client","user"]"
05:17:22    1> [2019-02-05T03:17:15,792][INFO ][o.e.c.m.MetaDataIndexTemplateService] [node_sm0] removing template [random_index_template]
05:17:22    1> [2019-02-05T03:17:15,821][INFO ][o.e.x.s.a.ApiKeyIntegTests] [testGetAndInvalidateApiKeysWithExpiredAndInvalidatedApiKey] [ApiKeyIntegTests#testGetAndInvalidateApiKeysWithExpiredAndInvalidatedApiKey]: cleaned up after test
05:17:22    1> [2019-02-05T03:17:15,821][INFO ][o.e.x.s.a.ApiKeyIntegTests] [testGetAndInvalidateApiKeysWithExpiredAndInvalidatedApiKey] after test
05:17:22  FAILURE 2.92s J5 | ApiKeyIntegTests.testGetAndInvalidateApiKeysWithExpiredAndInvalidatedApiKey <<< FAILURES!
05:17:22     > Throwable #1: java.lang.AssertionError: 
05:17:22     > Expected: <1>
05:17:22     >      but: was <0>
05:17:22     > 	at __randomizedtesting.SeedInfo.seed([D84FAE5E21AE11F0:82015FEC9C3DD7A3]:0)
05:17:22     > 	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
05:17:22     > 	at org.elasticsearch.xpack.security.authc.ApiKeyIntegTests.verifyInvalidateResponse(ApiKeyIntegTests.java:278)
05:17:22     > 	at org.elasticsearch.xpack.security.authc.ApiKeyIntegTests.testGetAndInvalidateApiKeysWithExpiredAndInvalidatedApiKey(ApiKeyIntegTests.java:261)
05:17:22     > 	at java.lang.Thread.run(Thread.java:748)
@jasontedor jasontedor added >test-failure Triaged test failures from CI :Security/Authentication Logging in, Usernames/passwords, Realms (Native/LDAP/AD/SAML/PKI/etc) labels Feb 5, 2019
@elasticmachine
Copy link
Collaborator

Pinging @elastic/es-security

@jasontedor
Copy link
Member Author

The reproduction line does not reproduce consistently.

@jasontedor jasontedor mentioned this issue Feb 5, 2019
Merged
@jasontedor
Copy link
Member Author

Muted in #38409.

bizybot pushed a commit to bizybot/elasticsearch that referenced this issue Feb 5, 2019
Enable logs for intermittent test failure
386744b 
I have not been able to reproduce the failing
test scenario locally for elastic#38408 and there are other similar
tests which are running fine in the same test class.
I am re-enabling the test with additional logs so
that we can debug further on what's happening.
I will keep the issue open for now and look out for the builds
to see if there are any related failures.
@bizybot bizybot mentioned this issue Feb 5, 2019
Merged
bizybot added a commit that referenced this issue Feb 6, 2019
@bizybot
Enable logs for intermittent test failure (#38426)
57600c5 
I have not been able to reproduce the failing
test scenario locally for #38408 and there are other similar
tests which are running fine in the same test class.
I am re-enabling the test with additional logs so
that we can debug further on what's happening.
I will keep the issue open for now and look out for the builds
to see if there are any related failures.
dnhatn added a commit to dnhatn/elasticsearch that referenced this issue Feb 6, 2019
@dnhatn
Mute testExpiredApiKeysDeletedAfter1Week in 6.7
3ce176e 
Tracked elastic#38408
@dnhatn dnhatn mentioned this issue Feb 6, 2019
Merged
dnhatn added a commit that referenced this issue Feb 6, 2019
@dnhatn
Mute testExpiredApiKeysDeletedAfter1Week in 6.7 (#38528)
5b6da65 
Tracked #38408
@jkakavas jkakavas mentioned this issue Feb 8, 2019
Closed
@cbuescher
Copy link
Member

@bizybot I saw you unmuted this test to get more logs, meanwhile it failed again at https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+periodic/688/consoleFull. Hopefully the logs contain some info you were looking for.

Since we're trying to stabilze master I muted it again in #38614, please feel free to revert if you need to continue running it to get more information.

@cbuescher
Copy link
Member

Another one: https://elasticsearch-ci.elastic.co/job/elastic+elasticsearch+master+multijob-unix-compatibility/os=ubuntu-16.04&&virtual/231/console
This should be muted now on master though.

bizybot referenced this issue in bizybot/elasticsearch Feb 8, 2019
Fix intermittent failure in ApiKeyIntegTests
80c69f7 
Few tests failed intermittently and most of the
times due to invalidate or expired keys that were
deleted were still reported in search results.

When ExpiredApiKeysRemover is triggered, the tests
did not await its termination thereby sometimes
the results would be wrong for a search operation.

DELETE_INTERVAL setting has been further reduced to
100ms so we can trigger ExpiredApiKeysRemover faster.

Closes#38408
@bizybot bizybot mentioned this issue Feb 8, 2019
Merged
tvernum pushed a commit to tvernum/elasticsearch that referenced this issue Feb 11, 2019
@dnhatn @tvernum
Mute testExpiredApiKeysDeletedAfter1Week
238c11a 
Tracked: elastic#38408
tvernum pushed a commit to tvernum/elasticsearch that referenced this issue Feb 11, 2019
@dnhatn @tvernum
Mute testExpiredApiKeysDeletedAfter1Week
7906525 
Tracked: elastic#38408
This was referenced Feb 11, 2019
Merged
Merged
tvernum pushed a commit to tvernum/elasticsearch that referenced this issue Feb 11, 2019
@dnhatn @tvernum
Mute testExpiredApiKeysDeletedAfter1Week
19ad1a1 
Tracked: elastic#38408
@tvernum tvernum mentioned this issue Feb 11, 2019
Merged
tvernum added a commit that referenced this issue Feb 11, 2019
@tvernum
Mute testExpiredApiKeysDeletedAfter1Week (#38682)
8a22a87 
Tracked: #38408
tvernum added a commit that referenced this issue Feb 11, 2019
@tvernum
Mute testExpiredApiKeysDeletedAfter1Week (#38683)
273edea 
Tracked: #38408
tvernum added a commit that referenced this issue Feb 11, 2019
@tvernum
Mute testExpiredApiKeysDeletedAfter1Week (#38684)
015cb8e 
Tracked: #38408
bizybot added a commit that referenced this issue Feb 15, 2019
@bizybot
Fix intermittent failure in ApiKeyIntegTests (#38627)
6a0531a 
Few tests failed intermittently and most of the
times due to invalidated or expired keys that were
deleted were still reported in search results.
This commit removes the test and adds enhancements
to other tests testing different scenario's.

When ExpiredApiKeysRemover is triggered, the tests
did not await its termination thereby sometimes
the results would be wrong for a search operation.

DELETE_INTERVAL setting has been further reduced to
100ms so we can trigger ExpiredApiKeysRemover faster.

Closes #38408
bizybot added a commit to bizybot/elasticsearch that referenced this issue Feb 15, 2019
@bizybot
Fix intermittent failure in ApiKeyIntegTests (elastic#38627)
8715098 
Few tests failed intermittently and most of the
times due to invalidated or expired keys that were
deleted were still reported in search results.
This commit removes the test and adds enhancements
to other tests testing different scenario's.

When ExpiredApiKeysRemover is triggered, the tests
did not await its termination thereby sometimes
the results would be wrong for a search operation.

DELETE_INTERVAL setting has been further reduced to
100ms so we can trigger ExpiredApiKeysRemover faster.

Closes elastic#38408
@bizybot bizybot mentioned this issue Feb 15, 2019
Merged
bizybot added a commit to bizybot/elasticsearch that referenced this issue Feb 15, 2019
@bizybot
Fix intermittent failure in ApiKeyIntegTests (elastic#38627)
1be7de6 
Few tests failed intermittently and most of the
times due to invalidated or expired keys that were
deleted were still reported in search results.
This commit removes the test and adds enhancements
to other tests testing different scenario's.

When ExpiredApiKeysRemover is triggered, the tests
did not await its termination thereby sometimes
the results would be wrong for a search operation.

DELETE_INTERVAL setting has been further reduced to
100ms so we can trigger ExpiredApiKeysRemover faster.

Closes elastic#38408
@bizybot bizybot mentioned this issue Feb 15, 2019
Merged
bizybot added a commit that referenced this issue Feb 15, 2019
@bizybot
Fix intermittent failure in ApiKeyIntegTests (#38627) (#38935)
36c2748 
Few tests failed intermittently and most of the
times due to invalidated or expired keys that were
deleted were still reported in search results.
This commit removes the test and adds enhancements
to other tests testing different scenario's.

When ExpiredApiKeysRemover is triggered, the tests
did not await its termination thereby sometimes
the results would be wrong for a search operation.

DELETE_INTERVAL setting has been further reduced to
100ms so we can trigger ExpiredApiKeysRemover faster.

Closes #38408
bizybot added a commit that referenced this issue Feb 15, 2019
@bizybot
Fix intermittent failure in ApiKeyIntegTests (#38627) (#38936)
86f1371 
Few tests failed intermittently and most of the
times due to invalidated or expired keys that were
deleted were still reported in search results.
This commit removes the test and adds enhancements
to other tests testing different scenario's.

When ExpiredApiKeysRemover is triggered, the tests
did not await its termination thereby sometimes
the results would be wrong for a search operation.

DELETE_INTERVAL setting has been further reduced to
100ms so we can trigger ExpiredApiKeysRemover faster.

Closes #38408
bizybot added a commit to bizybot/elasticsearch that referenced this issue Feb 15, 2019
@bizybot
Fix intermittent failure in ApiKeyIntegTests (elastic#38627)
fce0937 
Few tests failed intermittently and most of the
times due to invalidated or expired keys that were
deleted were still reported in search results.
This commit removes the test and adds enhancements
to other tests testing different scenario's.

When ExpiredApiKeysRemover is triggered, the tests
did not await its termination thereby sometimes
the results would be wrong for a search operation.

DELETE_INTERVAL setting has been further reduced to
100ms so we can trigger ExpiredApiKeysRemover faster.

Closes elastic#38408
bizybot added a commit to bizybot/elasticsearch that referenced this issue Feb 15, 2019
@bizybot
Fix intermittent failure in ApiKeyIntegTests (elastic#38627)
8922ac5 
Few tests failed intermittently and most of the
times due to invalidated or expired keys that were
deleted were still reported in search results.
This commit removes the test and adds enhancements
to other tests testing different scenario's.

When ExpiredApiKeysRemover is triggered, the tests
did not await its termination thereby sometimes
the results would be wrong for a search operation.

DELETE_INTERVAL setting has been further reduced to
100ms so we can trigger ExpiredApiKeysRemover faster.

Closes elastic#38408
@bizybot bizybot mentioned this issue Feb 15, 2019
Merged
bizybot added a commit that referenced this issue Feb 15, 2019
@bizybot
Fix intermittent failure in ApiKeyIntegTests (#38627) (#38959)
dd80f00 
Few tests failed intermittently and most of the
times due to invalidated or expired keys that were
deleted were still reported in search results.
This commit removes the test and adds enhancements
to other tests testing different scenario's.

When ExpiredApiKeysRemover is triggered, the tests
did not await its termination thereby sometimes
the results would be wrong for a search operation.

DELETE_INTERVAL setting has been further reduced to
100ms so we can trigger ExpiredApiKeysRemover faster.

Closes #38408
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@bizybot bizybot

Labels
:Security/Authentication Logging in, Usernames/passwords, Realms (Native/LDAP/AD/SAML/PKI/etc) >test-failure Triaged test failures from CI
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@bizybot @jasontedor @cbuescher @elasticmachine