elasticsearch icon indicating copy to clipboard operation
elasticsearch copied to clipboard

Published 20 hours ago • verified publisher icon elastic

[CI] EsqlAsyncSecurityIT testLimitedPrivilege failing

Open elasticsearchmachine opened this issue 1 year ago • 2 comments

Build Scans:

Reproduction Line:

./gradlew ":x-pack:plugin:esql:qa:security:javaRestTest" --tests "org.elasticsearch.xpack.esql.EsqlAsyncSecurityIT.testLimitedPrivilege" -Dtests.seed=C39B430C8E1344A9 -Dtests.locale=ar-IQ -Dtests.timezone=America/Menominee -Druntime.java=22

Applicable branches: main

Reproduces locally?: N/A

Failure History: See dashboard

Failure Message:

java.lang.AssertionError: 
Expected: a string containing "unauthorized for user [test-admin] run as [alias_user2] with effective roles [alias_user2] on indices [index-user2]"
     but: was "{"error":{"root_cause":[{"type":"resource_not_found_exception","reason":"FmVUd0pWZ1MtVHUtWmpWZFQxMHBjSHcbN3JlWFZfd2dRX2F0MXk5LVZORzlMZzo2Mjc4","stack_trace":"org.elasticsearch.ResourceNotFoundException: FmVUd0pWZ1MtVHUtWmpWZFQxMHBjSHcbN3JlWFZfd2dRX2F0MXk5LVZORzlMZzo2Mjc4\n\tat [email protected]/org.elasticsearch.xpack.core.async.AsyncTaskIndexService.lambda$getResponseFromIndex$5(AsyncTaskIndexService.java:428)\n\tat [email protected]/org.elasticsearch.action.ActionListenerImplementations$DelegatingFailureActionListener.onResponse(ActionListenerImplementations.java:218)\n\tat [email protected]/org.elasticsearch.action.support.ContextPreservingActionListener.onResponse(ContextPreservingActionListener.java:32)\n\tat [email protected]/org.elasticsearch.action.ActionListener$3.onResponse(ActionListener.java:399)\n\tat [email protected]/org.elasticsearch.tasks.TaskManager$1.onResponse(TaskManager.java:202)\n\tat [email protected]/org.elasticsearch.tasks.TaskManager$1.onResponse(TaskManager.java:196)\n\tat [email protected]/org.elasticsearch.action.ActionListenerImplementations$RunBeforeActionListener.onResponse(ActionListenerImplementations.java:335)\n\tat [email protected]/org.elasticsearch.action.ActionListener$3.onResponse(ActionListener.java:399)\n\tat [email protected]/org.elasticsearch.action.support.ContextPreservingActionListener.onResponse(ContextPreservingActionListener.java:32)\n\tat [email protected]/org.elasticsearch.action.ActionListenerImplementations$MappedActionListener.onResponse(ActionListenerImplementations.java:96)\n\tat [email protected]/org.elasticsearch.action.ActionListenerResponseHandler.handleResponse(ActionListenerResponseHandler.java:48)\n\tat [email protected]/org.elasticsearch.transport.TransportService$ContextRestoreResponseHandler.handleResponse(TransportService.java:1498)\n\tat [email protected]/org.elasticsearch.transport.TransportService$DirectResponseChannel.processResponse(TransportService.java:1595)\n\tat [email protected]/org.elasticsearch.transport.TransportService$DirectResponseChannel.sendResponse(TransportService.java:1569)\n\tat [email protected]/org.elasticsearch.transport.TaskTransportChannel.sendResponse(TaskTransportChannel.java:35)\n\tat [email protected]/org.elasticsearch.action.support.ChannelActionListener.onResponse(ChannelActionListener.java:32)\n\tat [email protected]/org.elasticsearch.action.support.ChannelActionListener.onResponse(ChannelActionListener.java:19)\n\tat [email protected]/org.elasticsearch.action.ActionListener.respondAndRelease(ActionListener.java:374)\n\tat [email protected]/org.elasticsearch.action.ActionRunnable$3.accept(ActionRunnable.java:78)\n\tat [email protected]/org.elasticsearch.action.ActionRunnable$3.accept(ActionRunnable.java:75)\n\tat [email protected]/org.elasticsearch.action.ActionRunnable$4.doRun(ActionRunnable.java:100)\n\tat [email protected]/org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:991)\n\tat [email protected]/org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:26)\n\tat java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)\n\tat java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)\n\tat java.base/java.lang.Thread.run(Thread.java:1570)\n"}],"type":"resource_not_found_exception","reason":"FmVUd0pWZ1MtVHUtWmpWZFQxMHBjSHcbN3JlWFZfd2dRX2F0MXk5LVZORzlMZzo2Mjc4","stack_trace":"org.elasticsearch.ResourceNotFoundException: FmVUd0pWZ1MtVHUtWmpWZFQxMHBjSHcbN3JlWFZfd2dRX2F0MXk5LVZORzlMZzo2Mjc4\n\tat [email protected]/org.elasticsearch.xpack.core.async.AsyncTaskIndexService.lambda$getResponseFromIndex$5(AsyncTaskIndexService.java:428)\n\tat [email protected]/org.elasticsearch.action.ActionListenerImplementations$DelegatingFailureActionListener.onResponse(ActionListenerImplementations.java:218)\n\tat [email protected]/org.elasticsearch.action.support.ContextPreservingActionListener.onResponse(ContextPreservingActionListener.java:32)\n\tat [email protected]/org.elasticsearch.action.ActionListener$3.onResponse(ActionListener.java:399)\n\tat [email protected]/org.elasticsearch.tasks.TaskManager$1.onResponse(TaskManager.java:202)\n\tat [email protected]/org.elasticsearch.tasks.TaskManager$1.onResponse(TaskManager.java:196)\n\tat [email protected]/org.elasticsearch.action.ActionListenerImplementations$RunBeforeActionListener.onResponse(ActionListenerImplementations.java:335)\n\tat [email protected]/org.elasticsearch.action.ActionListener$3.onResponse(ActionListener.java:399)\n\tat [email protected]/org.elasticsearch.action.support.ContextPreservingActionListener.onResponse(ContextPreservingActionListener.java:32)\n\tat [email protected]/org.elasticsearch.action.ActionListenerImplementations$MappedActionListener.onResponse(ActionListenerImplementations.java:96)\n\tat [email protected]/org.elasticsearch.action.ActionListenerResponseHandler.handleResponse(ActionListenerResponseHandler.java:48)\n\tat [email protected]/org.elasticsearch.transport.TransportService$ContextRestoreResponseHandler.handleResponse(TransportService.java:1498)\n\tat [email protected]/org.elasticsearch.transport.TransportService$DirectResponseChannel.processResponse(TransportService.java:1595)\n\tat [email protected]/org.elasticsearch.transport.TransportService$DirectResponseChannel.sendResponse(TransportService.java:1569)\n\tat [email protected]/org.elasticsearch.transport.TaskTransportChannel.sendResponse(TaskTransportChannel.java:35)\n\tat [email protected]/org.elasticsearch.action.support.ChannelActionListener.onResponse(ChannelActionListener.java:32)\n\tat [email protected]/org.elasticsearch.action.support.ChannelActionListener.onResponse(ChannelActionListener.java:19)\n\tat [email protected]/org.elasticsearch.action.ActionListener.respondAndRelease(ActionListener.java:374)\n\tat [email protected]/org.elasticsearch.action.ActionRunnable$3.accept(ActionRunnable.java:78)\n\tat [email protected]/org.elasticsearch.action.ActionRunnable$3.accept(ActionRunnable.java:75)\n\tat [email protected]/org.elasticsearch.action.ActionRunnable$4.doRun(ActionRunnable.java:100)\n\tat [email protected]/org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:991)\n\tat [email protected]/org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:26)\n\tat java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)\n\tat java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)\n\tat java.base/java.lang.Thread.run(Thread.java:1570)\n"},"status":404}"

Issue Reasons:

  • [main] 3 failures in test testLimitedPrivilege (1.7% fail rate in 180 executions)
  • [main] 2 failures in step part-4 (3.1% fail rate in 64 executions)
  • [main] 2 failures in pipeline elasticsearch-pull-request (3.1% fail rate in 64 executions)

Note: This issue was created using new test triage automation. Please report issues or feedback to es-delivery.

elasticsearchmachine avatar Aug 22 '24 15:08 elasticsearchmachine

This has been muted on branch main

Mute Reasons:

  • [main] 3 failures in test testLimitedPrivilege (1.7% fail rate in 180 executions)
  • [main] 2 failures in step part-4 (3.1% fail rate in 64 executions)
  • [main] 2 failures in pipeline elasticsearch-pull-request (3.1% fail rate in 64 executions)

Build Scans:

elasticsearchmachine avatar Aug 22 '24 15:08 elasticsearchmachine

Pinging @elastic/es-analytical-engine (Team:Analytics)

elasticsearchmachine avatar Aug 22 '24 15:08 elasticsearchmachine

After adding some logging here and there (async search indexing, bulk index transport action etc) I think the resource_not_found_exception comes from the fact that async id indexing is happening a bit too late and the get async id request is ahead of it:

[2024-08-28T16:41:54,853][INFO ][o.e.x.e.EsqlAsyncSecurityIT] [testLimitedPrivilege] REQUEST body={query=FROM first-alias,index-user1 METADATA _index | KEEP _index, org, value | LIMIT 10, keep_on_completion=true, wait_for_completion_timeout=204nanos, pragma={exchange_buffer_size=2, data_partitioning=segment, node_level_reduction=false}}
[2024-08-28T16:41:54,855][INFO ][o.e.x.c.a.AsyncExecutionId] [test-cluster-0] Encoding docId [XqccQit5TgSKBm2wn4EFnw] and taskId [DJtLxH5xRiqcghI3PxPBxQ:1881] into [FlhxY2NRaXQ1VGdTS0JtMnduNEVGbncbREp0THhINXhSaXFjZ2hJM1B4UEJ4UToxODgx]
[2024-08-28T16:41:54,857][INFO ][o.e.x.e.EsqlAsyncSecurityIT] [testLimitedPrivilege] RESPONSE=Response{requestLine=POST _query/async?error_trace=true HTTP/1.1, host=http://[::1]:53877, response=HTTP/1.1 200 OK}
[2024-08-28T16:41:54,857][INFO ][o.e.x.e.EsqlAsyncSecurityIT] [testLimitedPrivilege] is_running      : true
columns         : []
values          : []
id              : FlhxY2NRaXQ1VGdTS0JtMnduNEVGbncbREp0THhINXhSaXFjZ2hJM1B4UEJ4UToxODgx
[2024-08-28T16:41:54,857][INFO ][o.e.x.e.EsqlAsyncSecurityIT] [testLimitedPrivilege] REQUEST=Request{method='GET', endpoint='_query/async/FlhxY2NRaXQ1VGdTS0JtMnduNEVGbncbREp0THhINXhSaXFjZ2hJM1B4UEJ4UToxODgx?wait_for_completion_timeout=60s', params={error_trace=true}, options=RequestOptions{headers=es-security-runas-user: alias_user1}}
[2024-08-28T16:41:54,859][INFO ][stdout                   ] [test-cluster-0] Starting to index docId [XqccQit5TgSKBm2wn4EFnw] in async index [.async-search]
[2024-08-28T16:41:54,860][WARN ][o.e.x.e.EsqlAsyncSecurityIT] [testLimitedPrivilege] async id not found
org.elasticsearch.client.ResponseException: method [GET], host [http://[::1]:53877], URI [_query/async/FlhxY2NRaXQ1VGdTS0JtMnduNEVGbncbREp0THhINXhSaXFjZ2hJM1B4UEJ4UToxODgx?wait_for_completion_timeout=60s&error_trace=true], status line [HTTP/1.1 404 Not Found]
{"error":{"root_cause":[{"type":"resource_not_found_exception","reason":"FlhxY2NRaXQ1VGdTS0JtMnduNEVGbncbREp0THhINXhSaXFjZ2hJM1B4UEJ4UToxODgx","stack_trace":"org.elasticsearch.ResourceNotFoundException: FlhxY2NRaXQ1VGdTS0JtMnduNEVGbncbREp0THhINXhSaXFjZ2hJM1B4UEJ4UToxODgx\r\n\t
...
	at org.elasticsearch.client.RestClient.convertResponse(RestClient.java:351) ~[elasticsearch-rest-client-8.16.0-SNAPSHOT.jar:8.16.0-SNAPSHOT]
	at org.elasticsearch.client.RestClient.performRequest(RestClient.java:317) ~[elasticsearch-rest-client-8.16.0-SNAPSHOT.jar:8.16.0-SNAPSHOT]
	at org.elasticsearch.client.RestClient.performRequest(RestClient.java:292) ~[elasticsearch-rest-client-8.16.0-SNAPSHOT.jar:8.16.0-SNAPSHOT]
	at org.elasticsearch.xpack.esql.EsqlAsyncSecurityIT.runAsyncGet(EsqlAsyncSecurityIT.java:137) ~[javaRestTest/:?]
	at org.elasticsearch.xpack.esql.EsqlAsyncSecurityIT.runESQLCommand(EsqlAsyncSecurityIT.java:54) ~[javaRestTest/:?]
	at org.elasticsearch.xpack.esql.EsqlSecurityIT.lambda$testLimitedPrivilege$10(EsqlSecurityIT.java:298) ~[javaRestTest/:?]

[2024-08-28T16:41:54,863][INFO ][o.e.a.b.TransportBulkAction] [test-cluster-0] BULK response = IndexResponse[index=.async-search,id=XqccQit5TgSKBm2wn4EFnw,version=1,result=created,seqNo=3,primaryTerm=1,shards={"total":1,"successful":1,"failed":0}]
[2024-08-28T16:41:54,863][INFO ][o.e.x.e.c.a.AsyncTaskManagementService] [test-cluster-0] stored ESQL search results for [FlhxY2NRaXQ1VGdTS0JtMnduNEVGbncbREp0THhINXhSaXFjZ2hJM1B4UEJ4UToxODgx]
[2024-08-28T16:41:54,864][INFO ][o.e.x.e.EsqlAsyncSecurityIT] [testLimitedPrivilege] Waiting for all cluster updates up to this moment to be processed
[2024-08-28T16:41:54,898][INFO ][o.e.c.m.MetadataDeleteIndexService] [test-cluster-0] [.async-search/14bf89lvQN25yZD30qIAAA] deleting index

astefan avatar Aug 28 '24 14:08 astefan