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

Failing test: X-Pack Security API Integration Tests (Audit Log).x-pack/test/security_api_integration/tests/audit/audit_log·ts - security APIs - Audit Log Audit Log logs audit events when reading and writing saved objects #119267

Closed
kibanamachine opened this issue Nov 21, 2021 · 38 comments · Fixed by #132510, #154935, #176115 or #187869
Closed

Failing test: X-Pack Security API Integration Tests (Audit Log).x-pack/test/security_api_integration/tests/audit/audit_log·ts - security APIs - Audit Log Audit Log logs audit events when reading and writing saved objects #119267

kibanamachine opened this issue Nov 21, 2021 · 38 comments · Fixed by #132510, #154935, #176115 or #187869
Assignees
@elena-shostak
Labels
failed-test A test failure on a tracked branch, potentially flaky-test impact:needs-assessment Product and/or Engineering needs to evaluate the impact of the change. loe:small Small Level of Effort Team:Security Team focused on: Auth, Users, Roles, Spaces, Audit Logging, and more!

Comments

@kibanamachine
Copy link
Contributor

kibanamachine commented Nov 21, 2021 •
edited
Loading

A test failed on a tracked branch

SyntaxError: Unexpected end of JSON input
    at JSON.parse (<anonymous>)
    at map (test/security_api_integration/tests/audit/audit_log.ts:25:36)
    at Array.map (<anonymous>)
    at FileWrapper.readJSON (test/security_api_integration/tests/audit/audit_log.ts:25:20)
    at Context.<anonymous> (test/security_api_integration/tests/audit/audit_log.ts:52:23)
    at Object.apply (/opt/local-ssd/buildkite/builds/kb-n2-4-d324bf799483ae76/elastic/kibana-hourly/kibana/node_modules/@kbn/test/target_node/functional_test_runner/lib/mocha/wrap_function.js:87:16)

First failure: CI Build - 8.0
@kibanamachine kibanamachine added the failed-test A test failure on a tracked branch, potentially flaky-test label Nov 21, 2021
@botelastic botelastic bot added the needs-team Issues missing a team label label Nov 21, 2021
@mistic mistic added the Team:Security Team focused on: Auth, Users, Roles, Spaces, Audit Logging, and more! label Nov 22, 2021
@elasticmachine
Copy link
Contributor

Pinging @elastic/kibana-security (Team:Security)

@botelastic botelastic bot removed the needs-team Issues missing a team label label Nov 22, 2021
@jportner
Copy link
Contributor

These tests have been around for over a year without any issues, this looks like a transient failure. I'll close it for now, if it reopens we can investigate it further.

@kibanamachine
Copy link
Contributor Author

New failure: CI Build - 8.0

@kibanamachine kibanamachine reopened this Dec 3, 2021
@jportner jportner mentioned this issue Dec 3, 2021
Merged
@jportner
Copy link
Contributor

jportner commented Dec 3, 2021

This is starting to look like a pattern but I'm not sure what's causing it. I opened #120354 to give us more details in these error messages

@kibanamachine
Copy link
Contributor Author

New failure: CI Build - main

@jportner
Copy link
Contributor

jportner commented Dec 7, 2021 •
edited
Loading

New more detailed error message:

└-> logs audit events when reading and writing saved objects
--
  | └-> "before each" hook: global before each for "logs audit events when reading and writing saved objects"
  | └-> "before each" hook for "logs audit events when reading and writing saved objects"
  | └- ✖ fail: security APIs - Audit Log Audit Log logs audit events when reading and writing saved objects
  | │      Error: Failed to parse audit log JSON, error: "Unexpected end of JSON input", audit.log contents:
  | │ {"event":{"action":"http_request","category":["web"],"outcome":"unknown"},"http":{"request":{"method":"get"}},"url":{"domain":"localhost","path":"/audit_log","port":6101,"query":"query=param","scheme":"http"},"user":{"name":"elastic","roles":["superuser"]},"kibana":{"space_id":"default"},"trace":{"id":"b8cbaf03-5c1d-48b6-abd8-a0df0a5b3a85"},"ecs":{"version":"8.0.0"},"@timestamp":"2021-12-07T11:42:37.896+00:00","message":"User is requesting [/audit_log] endpoint","log":{"level":"INFO","logger":"plugins.security.audit.ecs"},"process":{"pid":12399},"transaction":{"id":"9965993cd18e923e"}}
  | │ {"event":{"action":"saved_object_create","category":["database"],"type":["creation"],"outcome":"unknown"},"kibana":{"space_id":"default","saved_object":{"type":"dashboard","id":"c6fc21b0-5752-11ec-b57d-2d2a69d33f32"}},"user":{"name":"elastic","roles":["superuser"]},"trace":{"id":"b8cbaf03-5c1d-48b6-abd8-a0df0a5b3a85"},"ecs":{"version":"8.0.0"},"@timestamp":"2021-12-07T11:42:38.013+00:00","message":"User is creating dashboard [id=c6fc21b0-5752-11ec-b57d-2d2a69d33f32]","log":{"level":"INFO","logger":"plugins.security.audit.ecs"},"process":{"pid":12399},"transaction":{"id":"9965993cd18e923e"}}
  | │ {"event":{"action":"saved_object_find","category":["database"],"type":["access"],"outcome":"success"},"kibana":{"space_id":"default","saved_object":{"type":"dashboard","id":"elastic_agent-f47f18cc-9c7d-4278-b2ea-a6dee816d395"}},"user":{"name":"elastic","roles":["superuser"]},"trace":{"id":"b8cbaf03-5c1d-48b6-abd8-a0df0a5b3a85"},"ecs":{"version":"8.0.0"},"@timestamp":"2021-12-07T11:42:39.163+00:00","message":"User has accessed dashboard [id=elastic_agent-f47f18cc-9c7d-4278-b2ea-a6dee816d395]","log":{"level":"INFO","logger":"plugins.security.audit.ecs"},"process":{"pid":12399},"transaction":{"id":"9965993cd18e923e"}}
  | │ {"event":{"action":"saved_object_find","category":["database"],"type":["access"],"outcome":"success"},"kibana":{"space_id":"default","saved_object":{"type":"dashboard","id":"system-d401ef40-a7d5-11e9-a422-d144027429da"}},"user":{"name":"elastic","roles":["superuser"]},"trace":{"id":"b8cbaf03-5c1d-48b6-abd8-a0df0a5b3a85"},"ecs":{"version":"8.0.0"},"@timestamp":"2021-12-07T11:42:39.164+00:00","message":"User has accessed dashboard [id=system-d401ef40-a7d5-11e9-a422-d144027429da]","log":{"level":"INFO","logger":"plugins.security.audit.ecs"},"process":{"pid":12399},"transaction":{"id":"9965993cd18e923e"}}
  | │ {"event":{"action":"saved_object_find","category":["database"],"type":["access"],"outcome":"success"},"kibana":{"space_id":"default","saved_object":{"type":"dashboard","id":"system-f49f3170-9ffc-11ea-87e4-49f31ec44891"}},"user":{"name":"elastic","roles":["superuser"]},"trace":{"id":"b8cbaf03-5c1d-48b6-abd8-a0df0a5b3a85"},"ecs":{"version":"8.0.0"},"@timestamp":"2021-12-07T11:42:39.164+00:00","message":"User has accessed dashboard [id=system-f49f3170-9ffc-11ea-87e4-49f31ec44891]","log":{"level":"INFO","logger":"plugins.security.audit.ecs"},"process":{"pid":12399},"transaction":{"id":"9965993cd18e923e"}}
  | │ {"event":{"action":"saved_object_find","category":["database"],"type":["access"],"outcome":"success"},"kibana":{"space_id":"default","saved_object":{"type":"dashboard","id":"system-01c54730-fee6-11e9-8405-516218e3d268"}},"user":{"name":"elastic","roles":["superuser"]},"trace":{"id":"b8cbaf03-5c1d-48b6-abd8-a0df0a5b3a85"},"ecs":{"version":"8.0.0"},"@timestamp":"2021-12-07T11:42:39.164+00:00","message":"User has accessed dashboard [id=system-01c54730-fee6-11e9-8405-516218e3d268]","log":{"level":"INFO","logger":"plugins.security.audit.ecs"},"process":{"pid":12399},"transaction":{"id":"9965993cd18e923e"}}
  | │ {"event":{"action":"saved_object_find","category":["database"],"type":["access"],"outcome":"success"},"kibana":{"space_id":"default","saved_object":{"type":"dashboard","id":"system-035846a0-a249-11e9-a422-d144027429da"}},"user":{"name":"elastic","roles":["superuser"]},"trace":{"id":"b8cbaf03-5c1d-48b6-abd8-a0df0a5b3a85"},"ecs":{"version":"8.0.0"},"@timestamp":"2021-12-07T11:42:39.165+00:00","message":"User has accessed dashboard [id=system-035846a0-a2
  | │       at FileWrapper.readJSON (test/security_api_integration/tests/audit/audit_log.ts:29:13)

The last event cuts off in the middle of the message field:
{"event":{"action":"saved_object_find","category":["database"],"type":["access"],"outcome":"success"},"kibana":{"space_id":"default","saved_object":{"type":"dashboard","id":"system-035846a0-a249-11e9-a422-d144027429da"}},"user":{"name":"elastic","roles":["superuser"]},"trace":{"id":"b8cbaf03-5c1d-48b6-abd8-a0df0a5b3a85"},"ecs":{"version":"8.0.0"},"@timestamp":"2021-12-07T11:42:39.165+00:00","message":"User has accessed dashboard [id=system-035846a0-a2

@jportner
Copy link
Contributor

jportner commented Dec 7, 2021

From a discussion offline with some other Kibana folks:

Sounds kinda like timing issues. Buildkite introduced a bunch of new timing behaviors, perhaps some other rando commits have pushed the timing on this one over the edge.
We have similar sort of tests with the eventLog for alerting - FTS is writing log entries (to an index), FTR is reading to validate the right docs got written. We have that in a retry loop, waiting a second in between, to handle the timing issues. Has worked well for us.

We already have retry logic (that waits for the file to be non-empty), I think adding a short delay between that and the read/parse step would probably alleviate our issues, even though it's not an ideal fix.

@exalate-issue-sync exalate-issue-sync bot added impact:needs-assessment Product and/or Engineering needs to evaluate the impact of the change. loe:small Small Level of Effort labels Dec 8, 2021
@kibanamachine
Copy link
Contributor Author

New failure: CI Build - main

@kibanamachine
Copy link
Contributor Author

New failure: CI Build - 8.0

mistic added a commit that referenced this issue Dec 13, 2021
@mistic
skip flaky suite (#119267)
38aa34f
mistic added a commit that referenced this issue Dec 13, 2021
@mistic
skip flaky suite (#119267)
97bda08
@mistic
Copy link
Member

mistic commented Dec 13, 2021

This test keeps failing and looks flaky. Skipping for now.

main/8.1: 38aa34f
8.0: 97bda08

TinLe pushed a commit to TinLe/kibana that referenced this issue Dec 22, 2021
@mistic @TinLe
skip flaky suite (elastic#119267)
195138f
@legrego legrego mentioned this issue May 19, 2022
Merged
kibanamachine pushed a commit to kibanamachine/kibana that referenced this issue Feb 2, 2024
@jeramysoucy
Updates test file wrapper to deterministically detect file write comp…
623ed1d 
…letion (elastic#176115)

Closes elastic#119267

## Summary

Attempts to deterministically detect when a file is written in entirety
in order to resolve flaky test issues where parsed JSON is incomplete.

Flaky Test Runner:
https://buildkite.com/elastic/kibana-flaky-test-suite-runner/builds/5015

(cherry picked from commit f9125ba)
jeramysoucy added a commit to jeramysoucy/kibana that referenced this issue Feb 2, 2024
@jeramysoucy
Updates test file wrapper to deterministically detect file write comp…
b9f6b7a 
…letion (elastic#176115)

Closes elastic#119267

## Summary

Attempts to deterministically detect when a file is written in entirety
in order to resolve flaky test issues where parsed JSON is incomplete.

Flaky Test Runner:
https://buildkite.com/elastic/kibana-flaky-test-suite-runner/builds/5015

(cherry picked from commit f9125ba)

# Conflicts:
#	x-pack/test/security_api_integration/tests/anonymous/login.ts
#	x-pack/test/security_api_integration/tests/audit/audit_log.ts
#	x-pack/test/security_api_integration/tests/audit/file_wrapper.ts
#	x-pack/test/security_api_integration/tests/kerberos/kerberos_login.ts
#	x-pack/test/security_api_integration/tests/oidc/authorization_code_flow/oidc_auth.ts
#	x-pack/test/security_api_integration/tests/pki/pki_auth.ts
#	x-pack/test/security_api_integration/tests/saml/saml_login.ts
#	x-pack/test/security_api_integration/tests/token/audit.ts
kibanamachine added a commit that referenced this issue Feb 2, 2024
@kibanamachine @jeramysoucy
[8.12] Updates test file wrapper to deterministically detect file wri…
0e7f027 
…te completion (#176115) (#176161)

# Backport

This will backport the following commits from `main` to `8.12`:
- [Updates test file wrapper to deterministically detect file write
completion (#176115)](#176115)

<!--- Backport version: 9.4.3 -->

### Questions ?
Please refer to the [Backport tool
documentation](https://github.com/sqren/backport)

<!--BACKPORT [{"author":{"name":"Jeramy
Soucy","email":"jeramy.soucy@elastic.co"},"sourceCommit":{"committedDate":"2024-02-02T14:57:37Z","message":"Updates
test file wrapper to deterministically detect file write completion
(#176115)\n\nCloses #119267\r\n\r\n## Summary\r\n\r\nAttempts to
deterministically detect when a file is written in entirety\r\nin order
to resolve flaky test issues where parsed JSON is
incomplete.\r\n\r\nFlaky Test
Runner:\r\nhttps://buildkite.com/elastic/kibana-flaky-test-suite-runner/builds/5015","sha":"f9125ba079aeaa31fcd07e442cf6789c344452ec","branchLabelMapping":{"^v8.13.0$":"main","^v(\\d+).(\\d+).\\d+$":"$1.$2"}},"sourcePullRequest":{"labels":["Team:Security","release_note:skip","backport:all-open","v8.13.0"],"title":"Updates
test file wrapper to deterministically detect file write
completion","number":176115,"url":"https://github.com/elastic/kibana/pull/176115","mergeCommit":{"message":"Updates
test file wrapper to deterministically detect file write completion
(#176115)\n\nCloses #119267\r\n\r\n## Summary\r\n\r\nAttempts to
deterministically detect when a file is written in entirety\r\nin order
to resolve flaky test issues where parsed JSON is
incomplete.\r\n\r\nFlaky Test
Runner:\r\nhttps://buildkite.com/elastic/kibana-flaky-test-suite-runner/builds/5015","sha":"f9125ba079aeaa31fcd07e442cf6789c344452ec"}},"sourceBranch":"main","suggestedTargetBranches":[],"targetPullRequestStates":[{"branch":"main","label":"v8.13.0","branchLabelMappingKey":"^v8.13.0$","isSourceBranch":true,"state":"MERGED","url":"https://github.com/elastic/kibana/pull/176115","number":176115,"mergeCommit":{"message":"Updates
test file wrapper to deterministically detect file write completion
(#176115)\n\nCloses #119267\r\n\r\n## Summary\r\n\r\nAttempts to
deterministically detect when a file is written in entirety\r\nin order
to resolve flaky test issues where parsed JSON is
incomplete.\r\n\r\nFlaky Test
Runner:\r\nhttps://buildkite.com/elastic/kibana-flaky-test-suite-runner/builds/5015","sha":"f9125ba079aeaa31fcd07e442cf6789c344452ec"}}]}]
BACKPORT-->

Co-authored-by: Jeramy Soucy <jeramy.soucy@elastic.co>
jeramysoucy added a commit that referenced this issue Feb 2, 2024
@jeramysoucy
[7.17] Updates test file wrapper to deterministically detect file wri…
caa3916 
…te completion (#176115) (#176167)

# Backport

This will backport the following commits from `main` to `7.17`:
- [Updates test file wrapper to deterministically detect file write
completion (#176115)](#176115)

<!--- Backport version: 8.9.8 -->

### Questions ?
Please refer to the [Backport tool
documentation](https://github.com/sqren/backport)

<!--BACKPORT [{"author":{"name":"Jeramy
Soucy","email":"jeramy.soucy@elastic.co"},"sourceCommit":{"committedDate":"2024-02-02T14:57:37Z","message":"Updates
test file wrapper to deterministically detect file write completion
(#176115)\n\nCloses #119267\r\n\r\n## Summary\r\n\r\nAttempts to
deterministically detect when a file is written in entirety\r\nin order
to resolve flaky test issues where parsed JSON is
incomplete.\r\n\r\nFlaky Test
Runner:\r\nhttps://buildkite.com/elastic/kibana-flaky-test-suite-runner/builds/5015","sha":"f9125ba079aeaa31fcd07e442cf6789c344452ec","branchLabelMapping":{"^v8.13.0$":"main","^v(\\d+).(\\d+).\\d+$":"$1.$2"}},"sourcePullRequest":{"labels":["Team:Security","release_note:skip","backport:all-open","v8.13.0"],"number":176115,"url":"https://github.com/elastic/kibana/pull/176115","mergeCommit":{"message":"Updates
test file wrapper to deterministically detect file write completion
(#176115)\n\nCloses #119267\r\n\r\n## Summary\r\n\r\nAttempts to
deterministically detect when a file is written in entirety\r\nin order
to resolve flaky test issues where parsed JSON is
incomplete.\r\n\r\nFlaky Test
Runner:\r\nhttps://buildkite.com/elastic/kibana-flaky-test-suite-runner/builds/5015","sha":"f9125ba079aeaa31fcd07e442cf6789c344452ec"}},"sourceBranch":"main","suggestedTargetBranches":[],"targetPullRequestStates":[{"branch":"main","label":"v8.13.0","labelRegex":"^v8.13.0$","isSourceBranch":true,"state":"MERGED","url":"https://github.com/elastic/kibana/pull/176115","number":176115,"mergeCommit":{"message":"Updates
test file wrapper to deterministically detect file write completion
(#176115)\n\nCloses #119267\r\n\r\n## Summary\r\n\r\nAttempts to
deterministically detect when a file is written in entirety\r\nin order
to resolve flaky test issues where parsed JSON is
incomplete.\r\n\r\nFlaky Test
Runner:\r\nhttps://buildkite.com/elastic/kibana-flaky-test-suite-runner/builds/5015","sha":"f9125ba079aeaa31fcd07e442cf6789c344452ec"}},{"url":"https://github.com/elastic/kibana/pull/176161","number":176161,"branch":"8.12","state":"OPEN"}]}]
BACKPORT-->
fkanout pushed a commit to fkanout/kibana that referenced this issue Feb 7, 2024
@jeramysoucy @fkanout
Updates test file wrapper to deterministically detect file write comp…
2e4c963 
…letion (elastic#176115)

Closes elastic#119267

## Summary

Attempts to deterministically detect when a file is written in entirety
in order to resolve flaky test issues where parsed JSON is incomplete.

Flaky Test Runner:
https://buildkite.com/elastic/kibana-flaky-test-suite-runner/builds/5015
CoenWarmer pushed a commit to CoenWarmer/kibana that referenced this issue Feb 15, 2024
@jeramysoucy @CoenWarmer
Updates test file wrapper to deterministically detect file write comp…
efd0616 
…letion (elastic#176115)

Closes elastic#119267

## Summary

Attempts to deterministically detect when a file is written in entirety
in order to resolve flaky test issues where parsed JSON is incomplete.

Flaky Test Runner:
https://buildkite.com/elastic/kibana-flaky-test-suite-runner/builds/5015
@kibanamachine kibanamachine reopened this Feb 15, 2024
@kibanamachine
Copy link
Contributor Author

New failure: CI Build - main

@kibanamachine
Copy link
Contributor Author

New failure: CI Build - main

@kibanamachine
Copy link
Contributor Author

New failure: CI Build - main

@kibanamachine
Copy link
Contributor Author

New failure: CI Build - main

fkanout pushed a commit to fkanout/kibana that referenced this issue Mar 4, 2024
@jeramysoucy @fkanout
Updates test file wrapper to deterministically detect file write comp…
b0ee237 
…letion (elastic#176115)

Closes elastic#119267

## Summary

Attempts to deterministically detect when a file is written in entirety
in order to resolve flaky test issues where parsed JSON is incomplete.

Flaky Test Runner:
https://buildkite.com/elastic/kibana-flaky-test-suite-runner/builds/5015
@azasypkin azasypkin self-assigned this Mar 5, 2024
@kibanamachine
Copy link
Contributor Author

New failure: CI Build - main

mistic added a commit that referenced this issue Mar 6, 2024
@mistic
skip flaky suite (#119267)
b2ac0ed
@mistic
Copy link
Member

mistic commented Mar 6, 2024

Skipped.

main: b2ac0ed

@kibanamachine
Copy link
Contributor Author

New failure: CI Build - 8.13

@elena-shostak elena-shostak mentioned this issue Jul 10, 2024
Merged
2 tasks
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@elena-shostak elena-shostak

Labels
failed-test A test failure on a tracked branch, potentially flaky-test impact:needs-assessment Product and/or Engineering needs to evaluate the impact of the change. loe:small Small Level of Effort Team:Security Team focused on: Auth, Users, Roles, Spaces, Audit Logging, and more!
Projects
None yet
Milestone
No milestone
8 participants
@azasypkin @mistic @jportner @elasticmachine @kc13greiner @kibanamachine @jeramysoucy @elena-shostak