search

netbirdio / netbird

Connect your devices into a single secure private WireGuard®-based mesh network with SSO/MFA and simple access controls.
https://netbird.io
BSD 3-Clause "New" or "Revised" License
9.85k stars 427 forks source link

Keycloak idp timeout #1386

Open max06 opened 6 months ago

max06 commented 6 months ago

We're running a large keycloak instance utilizing federation with a ldap directory.

Following your instructions we created a frontend client and a backend client. Using an empty realm without federation works, using our regular realm with federation causes timeouts.

Logs show:

infrastructure_files-dashboard-1   | *** - - [13/Dec/2023:16:35:14 +0000] "GET /peers HTTP/1.1" 304 0 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/111.0" "-"
infrastructure_files-dashboard-1   | *** - - [13/Dec/2023:16:35:14 +0000] "GET /static/js/main.643f6421.js HTTP/1.1" 304 0 "https://netbird.***.**/peers" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/111.0" "-"
infrastructure_files-dashboard-1   | *** - - [13/Dec/2023:16:35:14 +0000] "GET /static/media/bars.460b15c2eff2efb309cd0df6df541052.svg HTTP/1.1" 200 356 "https://netbird.***.**/peers" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/111.0" "-"
infrastructure_files-management-1  | 2023-12-13T16:35:14Z INFO management/server/account.go:1518: overriding JWT Domain and DomainCategory claims since single account mode is enabled
infrastructure_files-management-1  | 2023-12-13T16:35:24Z ERRO management/server/http/middleware/access_control.go:46: failed to get user from claims: failed to get account with token claims context deadline exceeded (Client.Timeout or context cancellation while reading body)
infrastructure_files-management-1  | 2023-12-13T16:35:24Z ERRO management/server/http/util/util.go:80: got a handler error: invalid JWT
infrastructure_files-management-1  | 2023-12-13T16:35:24Z ERRO management/server/telemetry/http_api_metrics.go:181: HTTP response 3095261566: GET /api/users status 401

I'm not sure if it's good to fetch all users to keep the accounts synchronized all the time.

If there's another way to verify just that single user on login, it could probably solve this issue.

Adding @kbudde for updates.

surik commented 6 months ago

Hi @max06, can you share a bit more about the size of your Keycloak user directory? Additionally, for your tests, you can disable IDP Manager, you won't have email and name information for the users but you will be able to log. To do so in management.json set IdpManagerConfig.ManagerType to none.

max06 commented 6 months ago

Good morning @surik, thank you for your reply.

Roughly estimating... I'd say around 1000-1200 entries, including inactive users. All in ldap, keycloak has no local users.

We just tested another build with higher timeout (2 minutes). It takes roughly 30-35 seconds till

infrastructure_files-management-1  | 2023-12-14T10:58:54Z INFO management/server/account.go:1009: 1 entries received from IdP management
infrastructure_files-management-1  | 2023-12-14T10:58:54Z INFO management/server/account.go:1038: warmed up IDP cache with 1 entries

Once that happened, the login is fast and works. I'll also test disabling the idp manager this afternoon.

(... I'm currently a little bit lost about the why and how things are related. Just a matter of time and coffee...)

mlsmaycon commented 6 months ago

Hello @max06 , thanks for sharing the results of your test.

Keycloak has an issue open because of a similar case: https://github.com/keycloak/keycloak/issues/10005

The problem seems to be related to keycloak issuing a ldap search when we call the /users API.

We can increase the timeout and possibly make the API calls use pagination, but we need to evaluate that.

As we don't have a testing environment with such scale and you already built a custom version. Would run some tests for us?

max06 commented 6 months ago

Hello @mlsmaycon!

I think you're right - and we're currently also looking into options limiting the scope of user searches to improve that process.

I currently have a dedicated testing setup up and running - happy to run test all day long!

surik commented 6 months ago

@max06 could you please use this branch to perform some tests? https://github.com/netbirdio/netbird/commits/debug-keycloak-idp/

You need to have the flag --log-level debug set when running the management service. Please share the duration you'll get in Keycloak totalUsersCount took %d ms to handle debug log message

max06 commented 6 months ago

I'm sorry for the delay - too many meetings...

My colleague who created the version I tested with the increased timeout already left ... I can build a new version (your branch is currently running), I just don't know where to increase the timeout... if you could give me a filepath maybe? 🙈

surik commented 6 months ago

@max06 the branch above already includes a timeout increase.

max06 commented 6 months ago

Hum... then it's not what you're currently looking at. Your branch causes timeout errors again.

mlsmaycon commented 6 months ago

@max06 can you pull the latest changes from the debug-keycloak-idp branch? I've increased the timeout to 2 minutes and updated the log level to info

max06 commented 6 months ago

Okay, it's the correct timeout.

All the logs!

2023-12-14T15:26:14Z DEBG management/server/telemetry/http_api_metrics.go:201: request OPTIONS /api/users took 0 ms and finished with status 204
2023-12-14T15:26:14Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T15:26:14Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T15:26:14Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T15:26:14Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T15:26:14Z DEBG management/server/file_store.go:285: took 411ns to acquire global lock
2023-12-14T15:26:14Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T15:26:14Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T15:26:14Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore
2023-12-14T15:26:14Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:26:14Z DEBG management/server/account.go:1148: account cltdvho8aioc73abje9g not found in cache, reloading
2023-12-14T15:26:14Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T15:26:14Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T15:26:14Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T15:26:14Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T15:26:14Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T15:26:14Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T15:26:14Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T15:26:14Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T15:26:14Z INFO management/server/idp/keycloak.go:420: Keycloak totalUsersCount took 7 ms to handle
2023-12-14T15:27:14Z DEBG management/server/telemetry/http_api_metrics.go:201: request OPTIONS /api/users took 0 ms and finished with status 204
2023-12-14T15:27:14Z DEBG management/server/telemetry/http_api_metrics.go:201: request OPTIONS /api/users took 0 ms and finished with status 204
2023-12-14T15:27:14Z DEBG management/server/telemetry/http_api_metrics.go:201: request OPTIONS /api/groups took 0 ms and finished with status 204
2023-12-14T15:27:14Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T15:27:14Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T15:27:20Z INFO management/server/account.go:1009: 1 entries received from IdP management
2023-12-14T15:27:20Z INFO management/server/account.go:1038: warmed up IDP cache with 1 entries
2023-12-14T15:27:34Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T15:27:34Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T15:27:34Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T15:27:34Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T15:27:43Z DEBG management/server/account.go:1160: 720 entries received from IdP management
2023-12-14T15:27:43Z DEBG management/server/account.go:1129: skipping IDP App Meta update because accountID cltdvho8aioc73abje9g has been already set for user 553f5100-0d05-4dd3-98ee-1747c5da73c0
2023-12-14T15:27:43Z DEBG management/server/file_store.go:281: released global lock in 1m29.41322561s
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T15:27:43Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T15:27:43Z DEBG management/server/file_store.go:285: took 330ns to acquire global lock
2023-12-14T15:27:43Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/account.go:1129: skipping IDP App Meta update because accountID cltdvho8aioc73abje9g has been already set for user 553f5100-0d05-4dd3-98ee-1747c5da73c0
2023-12-14T15:27:43Z DEBG management/server/file_store.go:285: took 1m29.41378273s to acquire global lock
2023-12-14T15:27:43Z DEBG management/server/file_store.go:281: released global lock in 551.771µs
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/file_store.go:295: acquiring lock for account cltdvho8aioc73abje9g
2023-12-14T15:27:43Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/account.go:1129: skipping IDP App Meta update because accountID cltdvho8aioc73abje9g has been already set for user 553f5100-0d05-4dd3-98ee-1747c5da73c0
2023-12-14T15:27:43Z DEBG management/server/file_store.go:285: took 1m29.413943537s to acquire global lock
2023-12-14T15:27:43Z DEBG management/server/file_store.go:281: released global lock in 1m29.414282232s
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T15:27:43Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T15:27:43Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/account.go:1129: skipping IDP App Meta update because accountID cltdvho8aioc73abje9g has been already set for user 553f5100-0d05-4dd3-98ee-1747c5da73c0
2023-12-14T15:27:43Z DEBG management/server/file_store.go:285: took 1m29.413496085s to acquire global lock
2023-12-14T15:27:43Z DEBG management/server/file_store.go:281: released global lock in 1m29.41434392s
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T15:27:43Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T15:27:43Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/account.go:1129: skipping IDP App Meta update because accountID cltdvho8aioc73abje9g has been already set for user 553f5100-0d05-4dd3-98ee-1747c5da73c0
2023-12-14T15:27:43Z DEBG management/server/file_store.go:285: took 1m29.413750809s to acquire global lock
2023-12-14T15:27:43Z DEBG management/server/file_store.go:303: released lock for account cltdvho8aioc73abje9g in 876.35µs
2023-12-14T15:27:43Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T15:27:43Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T15:27:43Z DEBG management/server/file_store.go:281: released global lock in 1m29.413878343s
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T15:27:43Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T15:27:43Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/account.go:1129: skipping IDP App Meta update because accountID cltdvho8aioc73abje9g has been already set for user 553f5100-0d05-4dd3-98ee-1747c5da73c0
2023-12-14T15:27:43Z DEBG management/server/file_store.go:281: released global lock in 1m29.41410247s
2023-12-14T15:27:43Z DEBG management/server/file_store.go:285: took 1m29.414043647s to acquire global lock
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T15:27:43Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T15:27:43Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/account.go:1129: skipping IDP App Meta update because accountID cltdvho8aioc73abje9g has been already set for user 553f5100-0d05-4dd3-98ee-1747c5da73c0
2023-12-14T15:27:43Z DEBG management/server/file_store.go:285: took 1m29.414288715s to acquire global lock
2023-12-14T15:27:43Z DEBG management/server/file_store.go:281: released global lock in 1m29.414365932s
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T15:27:43Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/account.go:1129: skipping IDP App Meta update because accountID cltdvho8aioc73abje9g has been already set for user 553f5100-0d05-4dd3-98ee-1747c5da73c0
2023-12-14T15:27:43Z DEBG management/server/file_store.go:285: took 28.993856344s to acquire global lock
2023-12-14T15:27:43Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T15:27:43Z DEBG management/server/file_store.go:281: released global lock in 1m29.414777756s
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T15:27:43Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T15:27:43Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/account.go:1129: skipping IDP App Meta update because accountID cltdvho8aioc73abje9g has been already set for user 553f5100-0d05-4dd3-98ee-1747c5da73c0
2023-12-14T15:27:43Z DEBG management/server/file_store.go:285: took 8.981899324s to acquire global lock
2023-12-14T15:27:43Z DEBG management/server/file_store.go:281: released global lock in 28.994284911s
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T15:27:43Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T15:27:43Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/account.go:1129: skipping IDP App Meta update because accountID cltdvho8aioc73abje9g has been already set for user 553f5100-0d05-4dd3-98ee-1747c5da73c0
2023-12-14T15:27:43Z DEBG management/server/file_store.go:285: took 8.982187263s to acquire global lock
2023-12-14T15:27:43Z DEBG management/server/file_store.go:281: released global lock in 8.982256676s
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T15:27:43Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/account.go:1129: skipping IDP App Meta update because accountID cltdvho8aioc73abje9g has been already set for user 553f5100-0d05-4dd3-98ee-1747c5da73c0
2023-12-14T15:27:43Z DEBG management/server/file_store.go:285: took 2.554637ms to acquire global lock
2023-12-14T15:27:43Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T15:27:43Z DEBG management/server/file_store.go:281: released global lock in 8.982553831s
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T15:27:43Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T15:27:43Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/account.go:1129: skipping IDP App Meta update because accountID cltdvho8aioc73abje9g has been already set for user 553f5100-0d05-4dd3-98ee-1747c5da73c0
2023-12-14T15:27:43Z DEBG management/server/file_store.go:285: took 2.574576ms to acquire global lock
2023-12-14T15:27:43Z DEBG management/server/file_store.go:281: released global lock in 2.87608ms
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/file_store.go:295: acquiring lock for account cltdvho8aioc73abje9g
2023-12-14T15:27:43Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/account.go:1129: skipping IDP App Meta update because accountID cltdvho8aioc73abje9g has been already set for user 553f5100-0d05-4dd3-98ee-1747c5da73c0
2023-12-14T15:27:43Z DEBG management/server/file_store.go:285: took 2.568934ms to acquire global lock
2023-12-14T15:27:43Z DEBG management/server/file_store.go:281: released global lock in 2.89732ms
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/file_store.go:303: released lock for account cltdvho8aioc73abje9g in 275.514µs
2023-12-14T15:27:43Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T15:27:43Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T15:27:43Z DEBG management/server/file_store.go:295: acquiring lock for account cltdvho8aioc73abje9g
2023-12-14T15:27:43Z DEBG management/server/file_store.go:303: released lock for account cltdvho8aioc73abje9g in 4.108µs
2023-12-14T15:27:43Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T15:27:43Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T15:27:43Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/account.go:1129: skipping IDP App Meta update because accountID cltdvho8aioc73abje9g has been already set for user 553f5100-0d05-4dd3-98ee-1747c5da73c0
2023-12-14T15:27:43Z DEBG management/server/file_store.go:281: released global lock in 3.118281ms
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/file_store.go:285: took 3.014223ms to acquire global lock
2023-12-14T15:27:43Z DEBG management/server/telemetry/http_api_metrics.go:201: request GET /api/groups took 89418 ms and finished with status 200
2023-12-14T15:27:43Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/account.go:1129: skipping IDP App Meta update because accountID cltdvho8aioc73abje9g has been already set for user 553f5100-0d05-4dd3-98ee-1747c5da73c0
2023-12-14T15:27:43Z DEBG management/server/file_store.go:285: took 3.302171ms to acquire global lock
2023-12-14T15:27:43Z DEBG management/server/file_store.go:281: released global lock in 3.564751ms
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/file_store.go:295: acquiring lock for account cltdvho8aioc73abje9g
2023-12-14T15:27:43Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/account.go:1129: skipping IDP App Meta update because accountID cltdvho8aioc73abje9g has been already set for user 553f5100-0d05-4dd3-98ee-1747c5da73c0
2023-12-14T15:27:43Z DEBG management/server/file_store.go:285: took 2.951142ms to acquire global lock
2023-12-14T15:27:43Z DEBG management/server/file_store.go:281: released global lock in 3.661797ms
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/file_store.go:295: acquiring lock for account cltdvho8aioc73abje9g
2023-12-14T15:27:43Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/account.go:1129: skipping IDP App Meta update because accountID cltdvho8aioc73abje9g has been already set for user 553f5100-0d05-4dd3-98ee-1747c5da73c0
2023-12-14T15:27:43Z DEBG management/server/file_store.go:285: took 3.166032ms to acquire global lock
2023-12-14T15:27:43Z DEBG management/server/file_store.go:303: released lock for account cltdvho8aioc73abje9g in 632.535µs
2023-12-14T15:27:43Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T15:27:43Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T15:27:43Z DEBG management/server/file_store.go:281: released global lock in 3.288735ms
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/file_store.go:295: acquiring lock for account cltdvho8aioc73abje9g
2023-12-14T15:27:43Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/account.go:1129: skipping IDP App Meta update because accountID cltdvho8aioc73abje9g has been already set for user 553f5100-0d05-4dd3-98ee-1747c5da73c0
2023-12-14T15:27:43Z DEBG management/server/file_store.go:285: took 3.292793ms to acquire global lock
2023-12-14T15:27:43Z DEBG management/server/file_store.go:281: released global lock in 3.602343ms
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/file_store.go:295: acquiring lock for account cltdvho8aioc73abje9g
2023-12-14T15:27:43Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/account.go:1129: skipping IDP App Meta update because accountID cltdvho8aioc73abje9g has been already set for user 553f5100-0d05-4dd3-98ee-1747c5da73c0
2023-12-14T15:27:43Z DEBG management/server/file_store.go:285: took 3.026867ms to acquire global lock
2023-12-14T15:27:43Z DEBG management/server/file_store.go:281: released global lock in 3.622341ms
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/file_store.go:295: acquiring lock for account cltdvho8aioc73abje9g
2023-12-14T15:27:43Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/account.go:1129: skipping IDP App Meta update because accountID cltdvho8aioc73abje9g has been already set for user 553f5100-0d05-4dd3-98ee-1747c5da73c0
2023-12-14T15:27:43Z DEBG management/server/file_store.go:285: took 3.356375ms to acquire global lock
2023-12-14T15:27:43Z DEBG management/server/file_store.go:281: released global lock in 3.452838ms
2023-12-14T15:27:43Z DEBG management/server/file_store.go:303: released lock for account cltdvho8aioc73abje9g in 994.554µs
2023-12-14T15:27:43Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T15:27:43Z DEBG management/server/file_store.go:303: released lock for account cltdvho8aioc73abje9g in 1.43269ms
2023-12-14T15:27:43Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T15:27:43Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/file_store.go:295: acquiring lock for account cltdvho8aioc73abje9g
2023-12-14T15:27:43Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/file_store.go:303: released lock for account cltdvho8aioc73abje9g in 1.111257ms
2023-12-14T15:27:43Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T15:27:43Z DEBG management/server/file_store.go:303: released lock for account cltdvho8aioc73abje9g in 297.487µs
2023-12-14T15:27:43Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T15:27:43Z DEBG management/server/file_store.go:303: released lock for account cltdvho8aioc73abje9g in 790.286µs
2023-12-14T15:27:43Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T15:27:43Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T15:27:43Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T15:27:43Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T15:27:43Z DEBG management/server/account.go:1129: skipping IDP App Meta update because accountID cltdvho8aioc73abje9g has been already set for user 553f5100-0d05-4dd3-98ee-1747c5da73c0
2023-12-14T15:27:43Z DEBG management/server/file_store.go:285: took 3.35886ms to acquire global lock
2023-12-14T15:27:43Z DEBG management/server/file_store.go:281: released global lock in 3.965906ms
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T15:27:43Z DEBG management/server/file_store.go:295: acquiring lock for account cltdvho8aioc73abje9g
2023-12-14T15:27:43Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/account.go:1129: skipping IDP App Meta update because accountID cltdvho8aioc73abje9g has been already set for user 553f5100-0d05-4dd3-98ee-1747c5da73c0
2023-12-14T15:27:43Z DEBG management/server/file_store.go:285: took 3.769782ms to acquire global lock
2023-12-14T15:27:43Z DEBG management/server/file_store.go:281: released global lock in 3.875254ms
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/file_store.go:295: acquiring lock for account cltdvho8aioc73abje9g
2023-12-14T15:27:43Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/account.go:1129: skipping IDP App Meta update because accountID cltdvho8aioc73abje9g has been already set for user 553f5100-0d05-4dd3-98ee-1747c5da73c0
2023-12-14T15:27:43Z DEBG management/server/file_store.go:285: took 2.370046ms to acquire global lock
2023-12-14T15:27:43Z DEBG management/server/file_store.go:303: released lock for account cltdvho8aioc73abje9g in 617.756µs
2023-12-14T15:27:43Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T15:27:43Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T15:27:43Z DEBG management/server/file_store.go:303: released lock for account cltdvho8aioc73abje9g in 193.377µs
2023-12-14T15:27:43Z DEBG management/server/file_store.go:281: released global lock in 4.08869ms
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/telemetry/http_api_metrics.go:201: request GET /api/routes took 89422 ms and finished with status 200
2023-12-14T15:27:43Z DEBG management/server/telemetry/http_api_metrics.go:201: request GET /api/accounts took 89422 ms and finished with status 200
2023-12-14T15:27:43Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/account.go:1129: skipping IDP App Meta update because accountID cltdvho8aioc73abje9g has been already set for user 553f5100-0d05-4dd3-98ee-1747c5da73c0
2023-12-14T15:27:43Z DEBG management/server/file_store.go:285: took 1.964584ms to acquire global lock
2023-12-14T15:27:43Z DEBG management/server/file_store.go:281: released global lock in 3.248449ms
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/file_store.go:295: acquiring lock for account cltdvho8aioc73abje9g
2023-12-14T15:27:43Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/account.go:1129: skipping IDP App Meta update because accountID cltdvho8aioc73abje9g has been already set for user 553f5100-0d05-4dd3-98ee-1747c5da73c0
2023-12-14T15:27:43Z DEBG management/server/file_store.go:285: took 2.04163ms to acquire global lock
2023-12-14T15:27:43Z DEBG management/server/file_store.go:281: released global lock in 2.475747ms
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/file_store.go:295: acquiring lock for account cltdvho8aioc73abje9g
2023-12-14T15:27:43Z DEBG management/server/file_store.go:303: released lock for account cltdvho8aioc73abje9g in 414.981µs
2023-12-14T15:27:43Z DEBG management/server/telemetry/http_api_metrics.go:201: request GET /api/policies took 89422 ms and finished with status 200
2023-12-14T15:27:43Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/account.go:1129: skipping IDP App Meta update because accountID cltdvho8aioc73abje9g has been already set for user 553f5100-0d05-4dd3-98ee-1747c5da73c0
2023-12-14T15:27:43Z DEBG management/server/file_store.go:303: released lock for account cltdvho8aioc73abje9g in 330.92µs
2023-12-14T15:27:43Z DEBG management/server/file_store.go:281: released global lock in 2.602518ms
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/file_store.go:295: acquiring lock for account cltdvho8aioc73abje9g
2023-12-14T15:27:43Z DEBG management/server/file_store.go:303: released lock for account cltdvho8aioc73abje9g in 5.29µs
2023-12-14T15:27:43Z DEBG management/server/telemetry/http_api_metrics.go:201: request GET /api/setup-keys took 89423 ms and finished with status 200
2023-12-14T15:27:43Z DEBG management/server/telemetry/http_api_metrics.go:201: request GET /api/dns/nameservers took 89423 ms and finished with status 200
2023-12-14T15:27:43Z DEBG management/server/file_store.go:285: took 2.533227ms to acquire global lock
2023-12-14T15:27:43Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/account.go:1129: skipping IDP App Meta update because accountID cltdvho8aioc73abje9g has been already set for user 553f5100-0d05-4dd3-98ee-1747c5da73c0
2023-12-14T15:27:43Z DEBG management/server/file_store.go:285: took 3.223482ms to acquire global lock
2023-12-14T15:27:43Z DEBG management/server/file_store.go:281: released global lock in 3.297614ms
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/user.go:980: Got 0 users from ExternalCache for account cltdvho8aioc73abje9g
2023-12-14T15:27:43Z DEBG management/server/user.go:981: Got 1 users from InternalCache for account cltdvho8aioc73abje9g
2023-12-14T15:27:43Z DEBG management/server/http/users_handler.go:201: UserCount: 1
2023-12-14T15:27:43Z DEBG management/server/http/users_handler.go:214: Should include service user: false
2023-12-14T15:27:43Z DEBG management/server/telemetry/http_api_metrics.go:201: request GET /api/users took 89424 ms and finished with status 200
2023-12-14T15:27:43Z DEBG management/server/account.go:1129: skipping IDP App Meta update because accountID cltdvho8aioc73abje9g has been already set for user 553f5100-0d05-4dd3-98ee-1747c5da73c0
2023-12-14T15:27:43Z DEBG management/server/file_store.go:285: took 4.00517ms to acquire global lock
2023-12-14T15:27:43Z DEBG management/server/file_store.go:281: released global lock in 4.107135ms
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/account.go:1129: skipping IDP App Meta update because accountID cltdvho8aioc73abje9g has been already set for user 553f5100-0d05-4dd3-98ee-1747c5da73c0
2023-12-14T15:27:43Z DEBG management/server/file_store.go:285: took 3.56404ms to acquire global lock
2023-12-14T15:27:43Z DEBG management/server/file_store.go:281: released global lock in 4.445569ms
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/account.go:1129: skipping IDP App Meta update because accountID cltdvho8aioc73abje9g has been already set for user 553f5100-0d05-4dd3-98ee-1747c5da73c0
2023-12-14T15:27:43Z DEBG management/server/file_store.go:281: released global lock in 3.953142ms
2023-12-14T15:27:43Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:43Z DEBG management/server/user.go:980: Got 0 users from ExternalCache for account cltdvho8aioc73abje9g
2023-12-14T15:27:43Z DEBG management/server/user.go:981: Got 1 users from InternalCache for account cltdvho8aioc73abje9g
2023-12-14T15:27:43Z DEBG management/server/http/users_handler.go:201: UserCount: 1
2023-12-14T15:27:43Z DEBG management/server/user.go:980: Got 0 users from ExternalCache for account cltdvho8aioc73abje9g
2023-12-14T15:27:43Z DEBG management/server/telemetry/http_api_metrics.go:201: request GET /api/users took 29004 ms and finished with status 200
2023-12-14T15:27:43Z DEBG management/server/telemetry/http_api_metrics.go:201: request GET /api/groups took 8992 ms and finished with status 200
2023-12-14T15:27:43Z DEBG management/server/user.go:981: Got 1 users from InternalCache for account cltdvho8aioc73abje9g
2023-12-14T15:27:43Z DEBG management/server/http/users_handler.go:201: UserCount: 1
2023-12-14T15:27:43Z DEBG management/server/telemetry/http_api_metrics.go:201: request GET /api/users took 8992 ms and finished with status 200
2023-12-14T15:27:44Z DEBG management/server/telemetry/http_api_metrics.go:201: request OPTIONS /api/peers took 0 ms and finished with status 204
2023-12-14T15:27:44Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T15:27:44Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T15:27:44Z DEBG management/server/file_store.go:285: took 240ns to acquire global lock
2023-12-14T15:27:44Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore
2023-12-14T15:27:44Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:44Z DEBG management/server/account.go:1129: skipping IDP App Meta update because accountID cltdvho8aioc73abje9g has been already set for user 553f5100-0d05-4dd3-98ee-1747c5da73c0
2023-12-14T15:27:44Z DEBG management/server/file_store.go:281: released global lock in 413.517µs
2023-12-14T15:27:44Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:44Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T15:27:44Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T15:27:44Z DEBG management/server/file_store.go:285: took 130ns to acquire global lock
2023-12-14T15:27:44Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore
2023-12-14T15:27:44Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:44Z DEBG management/server/account.go:1129: skipping IDP App Meta update because accountID cltdvho8aioc73abje9g has been already set for user 553f5100-0d05-4dd3-98ee-1747c5da73c0
2023-12-14T15:27:44Z DEBG management/server/file_store.go:281: released global lock in 377.559µs
2023-12-14T15:27:44Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:44Z DEBG management/server/file_store.go:295: acquiring lock for account cltdvho8aioc73abje9g
2023-12-14T15:27:44Z DEBG management/server/file_store.go:303: released lock for account cltdvho8aioc73abje9g in 7.824µs
2023-12-14T15:27:44Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T15:27:44Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T15:27:44Z DEBG management/server/file_store.go:285: took 210ns to acquire global lock
2023-12-14T15:27:44Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore
2023-12-14T15:27:44Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:44Z DEBG management/server/account.go:1129: skipping IDP App Meta update because accountID cltdvho8aioc73abje9g has been already set for user 553f5100-0d05-4dd3-98ee-1747c5da73c0
2023-12-14T15:27:44Z DEBG management/server/file_store.go:281: released global lock in 301.885µs
2023-12-14T15:27:44Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T15:27:44Z DEBG management/server/telemetry/http_api_metrics.go:201: request GET /api/peers took 2 ms and finished with status 200

Line 32 is interesting.

2023-12-14T15:27:43Z DEBG management/server/account.go:1160: 720 entries received from IdP management
mlsmaycon commented 6 months ago

Thanks @max06, I've pushed another version with some logs and an initial limit of 200 entries

We are just validating if pagination would improve performance and if the Link header is present in the response.

This will probably give you an error, so after running this version and getting the logs, you can rollback to the previous one.

max06 commented 6 months ago

There you go!

2023-12-14T17:05:26Z DEBG management/server/telemetry/http_api_metrics.go:201: request OPTIONS /api/users took 0 ms and finished with status 204
2023-12-14T17:05:26Z DEBG management/server/telemetry/http_api_metrics.go:201: request OPTIONS /api/setup-keys took 0 ms and finished with status 204
2023-12-14T17:05:26Z DEBG management/server/telemetry/http_api_metrics.go:201: request OPTIONS /api/groups took 0 ms and finished with status 204
2023-12-14T17:05:26Z DEBG management/server/telemetry/http_api_metrics.go:201: request OPTIONS /api/routes took 0 ms and finished with status 204
2023-12-14T17:05:26Z DEBG management/server/telemetry/http_api_metrics.go:201: request OPTIONS /api/policies took 0 ms and finished with status 204
2023-12-14T17:05:26Z DEBG management/server/telemetry/http_api_metrics.go:201: request OPTIONS /api/dns/nameservers took 0 ms and finished with status 204
2023-12-14T17:05:26Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T17:05:26Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T17:05:26Z DEBG management/server/file_store.go:285: took 380ns to acquire global lock
2023-12-14T17:05:26Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T17:05:26Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T17:05:26Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T17:05:26Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T17:05:26Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T17:05:26Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T17:05:26Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore
2023-12-14T17:05:26Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T17:05:26Z DEBG management/server/account.go:1148: account cltdvho8aioc73abje9g not found in cache, reloading
2023-12-14T17:05:26Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T17:05:26Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T17:05:26Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T17:05:26Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T17:05:26Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T17:05:26Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T17:05:26Z INFO management/server/idp/keycloak.go:412: Link header: 
2023-12-14T17:05:29Z INFO management/server/idp/keycloak.go:412: Link header: 
2023-12-14T17:05:48Z INFO management/server/account.go:1009: 1 entries received from IdP management
2023-12-14T17:05:48Z INFO management/server/account.go:1038: warmed up IDP cache with 1 entries
2023-12-14T17:05:51Z DEBG management/server/account.go:1160: 200 entries received from IdP management
2023-12-14T17:05:51Z DEBG management/server/account.go:1129: skipping IDP App Meta update because accountID cltdvho8aioc73abje9g has been already set for user 553f5100-0d05-4dd3-98ee-1747c5da73c0
2023-12-14T17:05:51Z DEBG management/server/file_store.go:281: released global lock in 24.969940854s
2023-12-14T17:05:51Z DEBG management/server/file_store.go:285: took 24.969926316s to acquire global lock
2023-12-14T17:05:51Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T17:05:51Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T17:05:51Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T17:05:51Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore
2023-12-14T17:05:51Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T17:05:51Z DEBG management/server/account.go:1129: skipping IDP App Meta update because accountID cltdvho8aioc73abje9g has been already set for user 553f5100-0d05-4dd3-98ee-1747c5da73c0
2023-12-14T17:05:51Z DEBG management/server/file_store.go:281: released global lock in 24.970710991s
2023-12-14T17:05:51Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T17:05:51Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T17:05:51Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T17:05:51Z DEBG management/server/file_store.go:285: took 200ns to acquire global lock
2023-12-14T17:05:51Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore
2023-12-14T17:05:51Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T17:05:51Z DEBG management/server/account.go:1129: skipping IDP App Meta update because accountID cltdvho8aioc73abje9g has been already set for user 553f5100-0d05-4dd3-98ee-1747c5da73c0
2023-12-14T17:05:51Z DEBG management/server/file_store.go:285: took 24.971138366s to acquire global lock
2023-12-14T17:05:51Z DEBG management/server/file_store.go:281: released global lock in 397.516µs
2023-12-14T17:05:51Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T17:05:51Z DEBG management/server/file_store.go:295: acquiring lock for account cltdvho8aioc73abje9g
2023-12-14T17:05:51Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore
2023-12-14T17:05:51Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T17:05:51Z DEBG management/server/account.go:1129: skipping IDP App Meta update because accountID cltdvho8aioc73abje9g has been already set for user 553f5100-0d05-4dd3-98ee-1747c5da73c0
2023-12-14T17:05:51Z DEBG management/server/file_store.go:281: released global lock in 24.971867725s
2023-12-14T17:05:51Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T17:05:51Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T17:05:51Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T17:05:51Z DEBG management/server/file_store.go:303: released lock for account cltdvho8aioc73abje9g in 224.808µs
2023-12-14T17:05:51Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T17:05:51Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T17:05:51Z DEBG management/server/file_store.go:285: took 24.97175484s to acquire global lock
2023-12-14T17:05:51Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore
2023-12-14T17:05:51Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache

Looks like the 200 users are good, but no link header.

mlsmaycon commented 6 months ago

@max06 I missed some of the startup logs. Can you get the full log from management?

max06 commented 6 months ago

Whoops, sorry. Yes, sure.

2023-12-14T17:05:24Z INFO management/cmd/management.go:422: loading OIDC configuration from the provided IDP configuration endpoint https://keycloak.somedomain/realms/somerealm/.well-known/openid-configuration
2023-12-14T17:05:24Z INFO management/cmd/management.go:427: loaded OIDC configuration from the provided IDP configuration endpoint: https://keycloak.somedomain/realms/somerealm/.well-known/openid-configuration
2023-12-14T17:05:24Z INFO management/cmd/management.go:429: overriding HttpConfig.AuthIssuer with a new value https://keycloak.somedomain/realms/somerealm, previously configured value: https://keycloak.somedomain/realms/somerealm
2023-12-14T17:05:24Z INFO management/cmd/management.go:433: overriding HttpConfig.AuthKeysLocation (JWT certs) with a new value https://keycloak.somedomain/realms/somerealm/protocol/openid-connect/certs, previously configured value: https://keycloak.somedomain/realms/somerealm/protocol/openid-connect/certs
2023-12-14T17:05:24Z INFO management/cmd/management.go:438: overriding DeviceAuthorizationFlow.TokenEndpoint with a new value: https://keycloak.somedomain/realms/somerealm/protocol/openid-connect/token, previously configured value: https://keycloak.somedomain/realms/somerealm/protocol/openid-connect/token
2023-12-14T17:05:24Z INFO management/cmd/management.go:441: overriding DeviceAuthorizationFlow.DeviceAuthEndpoint with a new value: https://keycloak.somedomain/realms/somerealm/protocol/openid-connect/auth/device, previously configured value: https://keycloak.somedomain/realms/somerealm/protocol/openid-connect/auth/device
2023-12-14T17:05:24Z INFO management/cmd/management.go:449: overriding DeviceAuthorizationFlow.ProviderConfig.Domain with a new value: keycloak.somedomain, previously configured value: keycloak.somedomain
2023-12-14T17:05:24Z INFO management/cmd/management.go:459: overriding PKCEAuthorizationFlow.TokenEndpoint with a new value: https://keycloak.somedomain/realms/somerealm/protocol/openid-connect/token, previously configured value: https://keycloak.somedomain/realms/somerealm/protocol/openid-connect/token
2023-12-14T17:05:24Z INFO management/cmd/management.go:462: overriding PKCEAuthorizationFlow.AuthorizationEndpoint with a new value: https://keycloak.somedomain/realms/somerealm/protocol/openid-connect/auth, previously configured value: https://keycloak.somedomain/realms/somerealm/protocol/openid-connect/auth
2023-12-14T17:05:24Z INFO management/server/telemetry/app_metrics.go:177: enabled application metrics and exposing on http://0.0.0.0:8081
2023-12-14T17:05:24Z INFO management/server/store.go:74: using JSON file store engine
2023-12-14T17:05:24Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore
2023-12-14T17:05:24Z DEBG management/server/activity/sqlite/sqlite.go:328: check deleted_users table version
2023-12-14T17:05:24Z INFO management/server/account.go:828: single account mode enabled, accounts number 1
2023-12-14T17:05:24Z DEBG management/server/idp/keycloak.go:125: requesting new jwt token for keycloak idp manager
2023-12-14T17:05:24Z DEBG management/server/ephemeral.go:135: loaded ephemeral peer(s): 0
2023/12/14 17:05:24 INFO: [core] [Server #1] Server created
2023-12-14T17:05:24Z INFO management/cmd/management.go:250: running gRPC backward compatibility server: [::]:33073
2023-12-14T17:05:24Z INFO management/cmd/management.go:282: running HTTP server and gRPC server on the same port: [::]:443
2023/12/14 17:05:24 INFO: [core] [Server #1 ListenSocket #2] ListenSocket created
2023-12-14T17:05:26Z DEBG management/server/telemetry/http_api_metrics.go:201: request OPTIONS /api/accounts took 0 ms and finished with status 204
2023-12-14T17:05:26Z DEBG management/server/telemetry/http_api_metrics.go:201: request OPTIONS /api/users took 0 ms and finished with status 204
2023-12-14T17:05:26Z DEBG management/server/telemetry/http_api_metrics.go:201: request OPTIONS /api/setup-keys took 0 ms and finished with status 204
2023-12-14T17:05:26Z DEBG management/server/telemetry/http_api_metrics.go:201: request OPTIONS /api/groups took 0 ms and finished with status 204
2023-12-14T17:05:26Z DEBG management/server/telemetry/http_api_metrics.go:201: request OPTIONS /api/routes took 0 ms and finished with status 204
2023-12-14T17:05:26Z DEBG management/server/telemetry/http_api_metrics.go:201: request OPTIONS /api/policies took 0 ms and finished with status 204
2023-12-14T17:05:26Z DEBG management/server/telemetry/http_api_metrics.go:201: request OPTIONS /api/dns/nameservers took 0 ms and finished with status 204
2023-12-14T17:05:26Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T17:05:26Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T17:05:26Z DEBG management/server/file_store.go:285: took 380ns to acquire global lock
2023-12-14T17:05:26Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T17:05:26Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T17:05:26Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T17:05:26Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T17:05:26Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T17:05:26Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T17:05:26Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore
2023-12-14T17:05:26Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T17:05:26Z DEBG management/server/account.go:1148: account cltdvho8aioc73abje9g not found in cache, reloading
2023-12-14T17:05:26Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T17:05:26Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T17:05:26Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T17:05:26Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T17:05:26Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T17:05:26Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T17:05:26Z INFO management/server/idp/keycloak.go:412: Link header: 
2023-12-14T17:05:29Z INFO management/server/idp/keycloak.go:412: Link header: 
2023-12-14T17:05:48Z INFO management/server/account.go:1009: 1 entries received from IdP management
2023-12-14T17:05:48Z INFO management/server/account.go:1038: warmed up IDP cache with 1 entries
2023-12-14T17:05:51Z DEBG management/server/account.go:1160: 200 entries received from IdP management
2023-12-14T17:05:51Z DEBG management/server/account.go:1129: skipping IDP App Meta update because accountID cltdvho8aioc73abje9g has been already set for user 553f5100-0d05-4dd3-98ee-1747c5da73c0
2023-12-14T17:05:51Z DEBG management/server/file_store.go:281: released global lock in 24.969940854s
2023-12-14T17:05:51Z DEBG management/server/file_store.go:285: took 24.969926316s to acquire global lock
2023-12-14T17:05:51Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache
2023-12-14T17:05:51Z INFO management/server/account.go:1524: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2023-12-14T17:05:51Z DEBG management/server/file_store.go:275: acquiring global lock
2023-12-14T17:05:51Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore
2023-12-14T17:05:51Z DEBG management/server/account.go:1210: looking up user 553f5100-0d05-4dd3-98ee-1747c5da73c0 of account cltdvho8aioc73abje9g in cache

If you're interested, I could open up a live share session for easier debugging.

mlsmaycon commented 6 months ago

Thanks, @max06 ; from your logs, it takes around 24s to get 200 users from the keycloak instance. This might give us around 96s for 4 requests, assuming 720 entries.

relevant logs:

# start log
2023-12-14T17:05:24Z INFO management/cmd/management.go:282: running HTTP server and gRPC server on the same port: [::]:443
# cache warm up log
2023-12-14T17:05:48Z INFO management/server/account.go:1009: 1 entries received from IdP management

We will discuss this option and get back to you. In the mean time, it seems that there was a progress with a PR fixing this from keycloak side: https://github.com/keycloak/keycloak/pull/19342