Add session cleanup audit logging #122419

thomheymann · 2022-01-06T09:46:30Z

Resolves: #119490

Summary

Add audit logging events for session cleanup

Testing

Configure Kibana:

xpack.security.audit.enabled: true
xpack.security.session.lifespan: "30s"
xpack.security.session.cleanupInterval: "10s"

Log in and immediately close the browser window
You should see the following event get logged in logs/audit.log after 40s

{
  "@timestamp": "2022-01-04T18:56:29.541+00:00",
  "message": "Removing invalid or expired session for user [hash=eb28536c8ead72bf81a0a9226e38fc9bad81f5e07c2081bb801b2a5c8842924e]",
  "event": {
    "action": "session_cleanup",
    "category": [
      "authentication"
    ],
    "outcome": "unknown"
  },
  "user": {
    "hash": "eb28536c8ead72bf81a0a9226e38fc9bad81f5e07c2081bb801b2a5c8842924e"
  },
  "kibana": {
    "session_id": "o6SMKslvp1Ab9Edhm118PqM/zmz9+0m4mWLIc5tA4pQ=",
    "authentication_provider": "basic",
    "authentication_type": "basic"
  }
}

elasticmachine · 2022-01-06T10:01:51Z

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

jportner

Some comments below.

Nice job on this so far, and I like the new audit-related TSdocs!

x-pack/plugins/security/server/session_management/session_index.test.ts

jportner · 2022-01-06T21:25:38Z

x-pack/plugins/security/server/session_management/session_index.ts

+      const { body: searchResponse } =
+        await this.options.elasticsearchClient.search<SessionIndexValue>(
+          {
+            index: this.indexName,
+            body: { query: { bool: { should: deleteQueries } } },
+            _source_includes: 'usernameHash,provider',
+          },
+          { ignore: [409, 404] }
        );
-      }


When we spoke about this last week we talked a bit about scale:

It's not very probable, but if an operator has Kibana configured to clean up sessions very infrequently and/or there are tons of users in a multi-Kibana setup, we could have lots of sessions to clean up, potentially hundreds of thousands.

I believe I suggested generating some test sessions in ES and, in a single task, attempting to delete up to 100k sessions (paging through 10k at a time, which is the max for any given search). This sounded like a reasonable starting point and I thought we should see how long it takes Kibana to do that -- we don't want to "clog up" the task manager, so we might need to dial that down depending on how long it takes (could ask folks in the Alerting team for input regarding this). Anything over that limit would simply be left for the next cleanup run to deal with.

Here are the docs for pagination:

By default, searches return the top 10 matching hits. To page through a larger set of results, you can use the search API's from and size parameters. The from parameter defines the number of hits to skip, defaulting to 0. The size parameter is the maximum number of hits to return. Together, these two parameters define a page of results.
...
By default, you cannot use from and size to page through more than 10,000 hits. This limit is a safeguard set by the index.max_result_window index setting. If you need to page through more than 10,000 hits, use the search_after parameter instead.

The way this code is currently written, Kibana will only find/delete at most 10 sessions during the cleanup phase.

This might be overkill, we could consider just finding/deleting 10k sessions per cleanup (240k per day by default) and leaving it at that. It would probably be fine for 99.99% of our users today, but I wonder if that will still be true 1, 2, or 5 years from now. Also, we can never predict exactly how users will (ab)use our configuration options 😄 we might have some folks who change their session cleanup interval to 30 days!

The pagination approach is more work, but it should allow us to delete up to an order of magnitude more expired sessions during each cleanup, and my gut feeling is that is the better thing to do.

Also, it might not be a bad idea to collect usage data on how many sessions are getting created / deleted every day.

Ah, good point, thanks! I mixed up the default with the maximum pagination size.

I've added pagination now so we're removing sessions in batches.

Sorry for the confusion on this...

Unfortunately you haven't actually added pagination since you're just using the size option, if there are 10,001 hits you've got an infinite loop because 1. you'll keep fetching the first 10k hits each time it loops, and 2. you are using hits.total which is the grand total for all hits (it's not the total for what was returned in this page).

You have to use either of these combinations:

size and from (for < 10k hits)

size and search_after (for any number of hits)

In either case you should really use a point-in-time (PIT), as specified in the search docs for pagination using search_after. If you don't do that, the index state could change between pages and your results will be incorrect.

In this situation we are concerned with there potentially being hundreds of thousands of results, so you should use size and search_after.

Also, I don't think you should use a page size of 1k, the size can be up to 10k. Since you aren't fetching a lot of fields, and this isn't a hot code path, I'd suggest using a size of 10k.

So you'll need to change this to:

Create a PIT

Page over 10k results at a time (up to 100k)

Log a warning if there are over 100k total hits

Clean up the PIT

Delete the expired sessions

I'd also like to see data on how this actually performs; we assume that 100k is a reasonable limit (I'd say that shouldn't take more than ~20s total) but we aren't certain. If you can generate some fake session data and run it locally to see how long the cleanup would take, that would be great. You could use console.time and console.timeEnd for that.

Hold on, I'm deleting the items that are being returned by the first batch. So next time I run the search I'm getting the next 1,000 sessions. I'm repeating that until there are no more sessions left in the index. Am I misunderstanding this?

Oh, I skimmed your changes and misread -- you're searching and deleting in each loop.

I had it in my head to page through all the objects then delete. Sorry about that. That's what I was implying with refresh: false, because if you don't refresh the index then your subsequent searches won't return fresh results.

You don't want to loop it like it's currently structured (search + delete in a single iteration) because then you'll be forced to use refresh: 'wait_for' each time you delete, which will really hurt performance.

EDIT: ~~for that matter, it would probably be a good idea to add a manual index refresh after the bulk-delete.~~

EDIT 2: the docs state:

By default, Elasticsearch periodically refreshes indices every second, but only on indices that have received one search request or more in the last 30 seconds.

Given that, I'm actually not sure if there will be any benefit to adding a manual index refresh, since we're the only ones searching the session index, and we only do this during cleanup. The index appears to automatically refresh shortly after the cleanup process completes.

x-pack/plugins/security/server/session_management/session_index.ts

…leanup

jportner

I mentioned that this needs to be tested with a large amount of expired sessions to make sure it works. I put together a sample archive of 100,005 expired sessions:
expired-sessions-archive.zip

First, I added some console logs to the cleanup code.

Then, I created this kibana.yml file:

elasticsearch.hosts: ["http://localhost:9200"]
elasticsearch.username: kibana
elasticsearch.password: changeme
xpack.security.session.cleanupInterval: "2m"

Then I started ES with yarn es snapshot and started Kibana with node scripts/kibana -c /path/to/kibana.yml (to run this in a production-like mode, without the base path proxy server)

Kibana immediately cleans up sessions when it starts, but I had to wait for it to finish doing fleet setup (it indexes a large amount of data into ES when it does that).

I waited about 2m and the cleanup happened again, at that point I loaded in the test archive:

node scripts/es_archiver.js --es-url http://elastic:changeme@localhost:9200 --kibana-url http://elastic:changeme@localhost:5601 load /path/to/expired-sessions-archive --docs-only

It take a while (~40-50 seconds) for that to complete.

Finally after another 2m had passed, the session cleanup happened again and 100k expired sessions got deleted. Another 2m later and the remaining 5 expired sessions got deleted:



[2022-01-12T11:47:59.367-05:00][INFO ][plugins.security.session.index] SESSION CLEANUP: deleting 10000 sessions...
[2022-01-12T11:48:00.012-05:00][INFO ][plugins.security.session.index] SESSION CLEANUP: deleting 10000 sessions...
[2022-01-12T11:48:00.361-05:00][INFO ][plugins.security.session.index] SESSION CLEANUP: deleting 10000 sessions...
[2022-01-12T11:48:00.694-05:00][INFO ][plugins.security.session.index] SESSION CLEANUP: deleting 10000 sessions...
[2022-01-12T11:48:00.956-05:00][INFO ][plugins.security.session.index] SESSION CLEANUP: deleting 10000 sessions...
[2022-01-12T11:48:01.234-05:00][INFO ][plugins.security.session.index] SESSION CLEANUP: deleting 10000 sessions...
[2022-01-12T11:48:01.502-05:00][INFO ][plugins.security.session.index] SESSION CLEANUP: deleting 10000 sessions...
[2022-01-12T11:48:01.764-05:00][INFO ][plugins.security.session.index] SESSION CLEANUP: deleting 10000 sessions...
[2022-01-12T11:48:02.071-05:00][INFO ][plugins.security.session.index] SESSION CLEANUP: deleting 10000 sessions...
[2022-01-12T11:48:02.654-05:00][INFO ][plugins.security.session.index] SESSION CLEANUP: deleting 10000 sessions...
SESSION CLEANUP: elapsed time 3.671s
[2022-01-12T11:50:02.284-05:00][INFO ][plugins.security.session.index] SESSION CLEANUP: deleting 5 sessions...
SESSION CLEANUP: elapsed time 71.2ms

I had to make some tweaks to get this working (see comments below). Overall nice job on this, it works really well and it's even faster than I expected 🎉

jportner · 2022-01-12T17:25:07Z

x-pack/plugins/security/server/session_management/session_index.ts

+    // Create point in time snapshot to paginate through sessions
+    const { body: pitResponse } = await this.options.elasticsearchClient.openPointInTime({
+      index: this.indexName,
+      keep_alive: SESSION_INDEX_CLEANUP_KEEP_ALIVE,
+    });


You need to close the PIT after you are finished searching (elasticsearchClient.closePointInTime)

jportner · 2022-01-12T17:34:40Z

x-pack/plugins/security/server/session_management/session_index.ts

+    // We don't know the total number of sessions until we fetched the first batch so assume we have at least one session to clean.
+    let total = 1;
+    let searchAfter: SortResults | undefined;
+    for (let i = 0; i < total / SESSION_INDEX_CLEANUP_BATCH_SIZE; i++) {
+      const { body: searchResponse } =
+        await this.options.elasticsearchClient.search<SessionIndexValue>({
+          pit: { id: pitResponse.id, keep_alive: SESSION_INDEX_CLEANUP_KEEP_ALIVE },
+          _source_includes: 'usernameHash,provider',
+          query: { bool: { should: deleteQueries } },
+          search_after: searchAfter,
+          size: SESSION_INDEX_CLEANUP_BATCH_SIZE,
+          sort: '_shard_doc',
+        });
+      if (searchResponse.hits.hits.length > 0) {
+        yield searchResponse.hits.hits;
+        total = (searchResponse.hits.total as SearchTotalHits).value;
+        searchAfter = searchResponse.hits.hits[searchResponse.hits.hits.length - 1].sort;
      }


I tested this and if you have > 10k sessions, this loop terminates after one iteration, because the total is > 10k.

I don't think you need to use the total here at all, in fact after looking into this a bit more, the total hits is not accurate for amounts > 10k anyway and we get a performance improvement if we disable it.

Furthermore, this loop has no limit, as I mentioned above we need some sort of limit.

I suggest changing the loop like so, I tested this and it worked well:

diff --git a/x-pack/plugins/security/server/session_management/session_index.ts b/x-pack/plugins/security/server/session_management/session_index.ts index 037c47ca791..554d917b834 100644 --- a/x-pack/plugins/security/server/session_management/session_index.ts +++ b/x-pack/plugins/security/server/session_management/session_index.ts @@ -7,7 +7,6 @@ import type { BulkOperationContainer, - SearchTotalHits, SortResults, } from '@elastic/elasticsearch/lib/api/typesWithBodyKey'; @@ -48,6 +47,12 @@ const SESSION_INDEX_TEMPLATE_VERSION = 1; */ const SESSION_INDEX_CLEANUP_BATCH_SIZE = 10_000; +/** + * Maximum number of batches per cleanup. + * If the batch size is 10,000 and this limit is 10, then Kibana will remove up to 100k sessions per cleanup. + */ +const SESSION_INDEX_CLEANUP_BATCH_LIMIT = 10; + /** * Number of sessions to remove per batch during cleanup. */ @@ -559,10 +564,8 @@ export class SessionIndex { keep_alive: SESSION_INDEX_CLEANUP_KEEP_ALIVE, }); - // We don't know the total number of sessions until we fetched the first batch so assume we have at least one session to clean. - let total = 1; let searchAfter: SortResults | undefined; - for (let i = 0; i < total / SESSION_INDEX_CLEANUP_BATCH_SIZE; i++) { + for (let i = 0; i < SESSION_INDEX_CLEANUP_BATCH_LIMIT; i++) { const { body: searchResponse } = await this.options.elasticsearchClient.search<SessionIndexValue>({ pit: { id: pitResponse.id, keep_alive: SESSION_INDEX_CLEANUP_KEEP_ALIVE }, @@ -571,11 +574,15 @@ export class SessionIndex { search_after: searchAfter, size: SESSION_INDEX_CLEANUP_BATCH_SIZE, sort: '_shard_doc', + track_total_hits: false, // for performance }); - if (searchResponse.hits.hits.length > 0) { - yield searchResponse.hits.hits; - total = (searchResponse.hits.total as SearchTotalHits).value; - searchAfter = searchResponse.hits.hits[searchResponse.hits.hits.length - 1].sort; + const { hits } = searchResponse.hits; + if (hits.length > 0) { + yield hits; + searchAfter = hits[hits.length - 1].sort; + if (hits.length < SESSION_INDEX_CLEANUP_BATCH_SIZE) { + break; + } } } }

In addition: can you please add two unit tests -- one for 10,001 sessions to demonstrate the loop terminates early, and one for 100,001 sessions to demonstrate that the loop doesn't exceed the configured limit.

jportner · 2022-01-12T17:35:53Z

x-pack/plugins/security/server/session_management/session_index.ts

+/**
+ * Number of sessions to remove per batch during cleanup.
+ */
+const SESSION_INDEX_CLEANUP_KEEP_ALIVE = '5m';


Suggested change

/**

* Number of sessions to remove per batch during cleanup.

*/

const SESSION_INDEX_CLEANUP_KEEP_ALIVE = '5m';

/**

* How long the session cleanup search point-in-time should be kept alive.

*/

const SESSION_INDEX_CLEANUP_KEEP_ALIVE = '5m';

…leanup

jportner

I ran it again with the existing debug logs enabled. This time I also enabled audit logs. It was almost as fast, took about 5s to delete 100k sessions.

[2022-01-12T15:13:27.195-05:00][DEBUG][plugins.security.session.index] Running cleanup routine.
[2022-01-12T15:13:28.214-05:00][DEBUG][plugins.security.session.index] Cleaned up 10000 invalid or expired sessions.
[2022-01-12T15:13:28.768-05:00][DEBUG][plugins.security.session.index] Cleaned up 10000 invalid or expired sessions.
[2022-01-12T15:13:29.197-05:00][DEBUG][plugins.security.session.index] Cleaned up 10000 invalid or expired sessions.
[2022-01-12T15:13:29.614-05:00][DEBUG][plugins.security.session.index] Cleaned up 10000 invalid or expired sessions.
[2022-01-12T15:13:30.004-05:00][DEBUG][plugins.security.session.index] Cleaned up 10000 invalid or expired sessions.
[2022-01-12T15:13:30.453-05:00][DEBUG][plugins.security.session.index] Cleaned up 10000 invalid or expired sessions.
[2022-01-12T15:13:30.857-05:00][DEBUG][plugins.security.session.index] Cleaned up 10000 invalid or expired sessions.
[2022-01-12T15:13:31.301-05:00][DEBUG][plugins.security.session.index] Cleaned up 10000 invalid or expired sessions.
[2022-01-12T15:13:31.714-05:00][DEBUG][plugins.security.session.index] Cleaned up 10000 invalid or expired sessions.
[2022-01-12T15:13:32.167-05:00][DEBUG][plugins.security.session.index] Cleaned up 10000 invalid or expired sessions.
[2022-01-12T15:15:30.237-05:00][DEBUG][plugins.security.session.index] Running cleanup routine.
[2022-01-12T15:15:30.302-05:00][DEBUG][plugins.security.session.index] Cleaned up 5 invalid or expired sessions.

Again, nice job 😄

kibana-ci · 2022-01-12T20:55:51Z

💚 Build Succeeded

Metrics [docs]

Public APIs missing comments

Total count of every public API that lacks a comment. Target amount is 0. Run node scripts/build_api_docs --plugin [yourplugin] --stats comments for more detailed information.

id	before	after	diff
`security`	104	102	-2

Unknown metric groups

API count

id	before	after	diff
`security`	180	181	+1

History

💚 Build #16854 succeeded abb1139
💔 Build #16456 failed 615d6a9
💚 Build #16095 succeeded 24d3ff6
💔 Build #16081 failed b759f46

To update your PR or re-run it, just comment with:
@elasticmachine merge upstream

* Add session cleanup audit logging * Update snapshots * Added suggestions from code review * Clean up sessions in batches * Added suggestions form code review (cherry picked from commit 39cef8b)

kibanamachine · 2022-01-12T23:04:31Z

💔 Some backports could not be created

Status	Branch	Result
✅	8.0
❌	7.17	Backport failed because of merge conflicts

How to fix

Re-run the backport manually:

node scripts/backport --pr 122419

Note: Successful backport PRs will be merged automatically after passing CI.

Questions ?

Please refer to the Backport tool documentation

thomheymann · 2022-01-13T08:37:51Z

We are going to keep hitting issues attempting to back-port any audit log changes to 7.x branch due to:

legacy audit logger having been removed from 8.x but not 7.x
user access agreement not having been back-ported to 7.x

If it's a business priority to back port to 7.x it can be done but I'd suggest to focus on 8.x for new audit logging capabilities.

kibanamachine · 2022-01-14T23:06:18Z

Looks like this PR has a backport PR but it still hasn't been merged. Please merge it ASAP to keep the branches relatively in sync.

kibanamachine · 2022-01-17T23:16:18Z

Looks like this PR has a backport PR but it still hasn't been merged. Please merge it ASAP to keep the branches relatively in sync.

* Add session cleanup audit logging (#122419) * Add session cleanup audit logging * Update snapshots * Added suggestions from code review * Clean up sessions in batches * Added suggestions form code review (cherry picked from commit 39cef8b) * Fix types Co-authored-by: Kibana Machine <42973632+kibanamachine@users.noreply.github.com>

Add session cleanup audit logging

b759f46

thomheymann requested a review from a team January 6, 2022 09:46

thomheymann marked this pull request as ready for review January 6, 2022 10:01

Update snapshots

24d3ff6

jportner removed the v8.2.0 label Jan 6, 2022

jportner reviewed Jan 6, 2022

View reviewed changes

thomheymann added 2 commits January 10, 2022 10:19

Merge branch 'main' of github.com:elastic/kibana into audit-session-c…

c6d98d9

…leanup

Added suggestions from code review

615d6a9

thomheymann requested a review from jportner January 10, 2022 16:09

thomheymann added 2 commits January 11, 2022 22:58

Clean up sessions in batches

5ed9bfb

Merge branch 'main' of github.com:elastic/kibana into audit-session-c…

abb1139

…leanup

jportner reviewed Jan 12, 2022

View reviewed changes

thomheymann added 2 commits January 12, 2022 19:36

Added suggestions form code review

52d61cd

Merge branch 'main' of github.com:elastic/kibana into audit-session-c…

9e70295

…leanup

jportner approved these changes Jan 12, 2022

View reviewed changes

thomheymann merged commit 39cef8b into elastic:main Jan 12, 2022

kibanamachine mentioned this pull request Jan 12, 2022

[8.0] Add session cleanup audit logging (#122419) #122898

Closed

kibanamachine added the backport missing Added to PRs automatically when the are determined to be missing a backport. label Jan 14, 2022

jportner removed the v7.17.0 label Jan 14, 2022

thomheymann mentioned this pull request Jan 18, 2022

[8.0] Add session cleanup audit logging (#122419) #122898 #123200

Merged

kibanamachine removed the backport missing Added to PRs automatically when the are determined to be missing a backport. label Jan 18, 2022

jportner mentioned this pull request Feb 1, 2022

[Discuss] [Kibana platform security] Session tracking and audit logging #91285

Closed

jportner mentioned this pull request Mar 4, 2022

Fix session cleanup test #126966

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add session cleanup audit logging #122419

Add session cleanup audit logging #122419

thomheymann commented Jan 6, 2022 •

edited

Loading

elasticmachine commented Jan 6, 2022

jportner left a comment

jportner Jan 6, 2022 •

edited

Loading

thomheymann Jan 10, 2022

jportner Jan 10, 2022 •

edited

Loading

thomheymann Jan 10, 2022

jportner Jan 10, 2022 •

edited

Loading

jportner left a comment

jportner Jan 12, 2022

jportner Jan 12, 2022

jportner Jan 12, 2022

jportner left a comment

kibana-ci commented Jan 12, 2022

API count

kibanamachine commented Jan 12, 2022

thomheymann commented Jan 13, 2022

kibanamachine commented Jan 14, 2022

kibanamachine commented Jan 17, 2022

Add session cleanup audit logging #122419

Add session cleanup audit logging #122419

Conversation

thomheymann commented Jan 6, 2022 • edited Loading

Summary

Testing

elasticmachine commented Jan 6, 2022

jportner left a comment

Choose a reason for hiding this comment

jportner Jan 6, 2022 • edited Loading

Choose a reason for hiding this comment

thomheymann Jan 10, 2022

Choose a reason for hiding this comment

jportner Jan 10, 2022 • edited Loading

Choose a reason for hiding this comment

thomheymann Jan 10, 2022

Choose a reason for hiding this comment

jportner Jan 10, 2022 • edited Loading

Choose a reason for hiding this comment

jportner left a comment

Choose a reason for hiding this comment

jportner Jan 12, 2022

Choose a reason for hiding this comment

jportner Jan 12, 2022

Choose a reason for hiding this comment

jportner Jan 12, 2022

Choose a reason for hiding this comment

jportner left a comment

Choose a reason for hiding this comment

kibana-ci commented Jan 12, 2022

💚 Build Succeeded

Metrics [docs]

Public APIs missing comments

API count

History

kibanamachine commented Jan 12, 2022

💔 Some backports could not be created

How to fix

Questions ?

thomheymann commented Jan 13, 2022

kibanamachine commented Jan 14, 2022

kibanamachine commented Jan 17, 2022

thomheymann commented Jan 6, 2022 •

edited

Loading

jportner Jan 6, 2022 •

edited

Loading

jportner Jan 10, 2022 •

edited

Loading

jportner Jan 10, 2022 •

edited

Loading