Keycloak idp timeout #544

Open
opened 2025-11-20 05:13:27 -05:00 by saavagebueno · 18 comments
Owner

Originally created by @max06 on GitHub (Dec 13, 2023).

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.

Originally created by @max06 on GitHub (Dec 13, 2023). 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: ```text 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.
saavagebueno added the needs-reviewmanagement-serviceidpkeycloak labels 2025-11-20 05:13:27 -05:00
Author
Owner

@surik commented on GitHub (Dec 14, 2023):

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.

@surik commented on GitHub (Dec 14, 2023): 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`.
Author
Owner

@max06 commented on GitHub (Dec 14, 2023):

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...)

@max06 commented on GitHub (Dec 14, 2023): 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 ```text 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...)
Author
Owner

@mlsmaycon commented on GitHub (Dec 14, 2023):

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?

@mlsmaycon commented on GitHub (Dec 14, 2023): 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?
Author
Owner

@max06 commented on GitHub (Dec 14, 2023):

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!

@max06 commented on GitHub (Dec 14, 2023): 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!
Author
Owner

@surik commented on GitHub (Dec 14, 2023):

@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

@surik commented on GitHub (Dec 14, 2023): @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
Author
Owner

@max06 commented on GitHub (Dec 14, 2023):

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? 🙈

@max06 commented on GitHub (Dec 14, 2023): 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? 🙈
Author
Owner

@surik commented on GitHub (Dec 14, 2023):

@max06 the branch above already includes a timeout increase.

@surik commented on GitHub (Dec 14, 2023): @max06 the branch above already includes a timeout increase.
Author
Owner

@max06 commented on GitHub (Dec 14, 2023):

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

@max06 commented on GitHub (Dec 14, 2023): Hum... then it's not what you're currently looking at. Your branch causes timeout errors again.
Author
Owner

@mlsmaycon commented on GitHub (Dec 14, 2023):

@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

@mlsmaycon commented on GitHub (Dec 14, 2023): @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
Author
Owner

@max06 commented on GitHub (Dec 14, 2023):

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
@max06 commented on GitHub (Dec 14, 2023): Okay, it's the correct timeout. All the logs! ```text 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. ```text 2023-12-14T15:27:43Z DEBG management/server/account.go:1160: 720 entries received from IdP management ```
Author
Owner

@mlsmaycon commented on GitHub (Dec 14, 2023):

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.

@mlsmaycon commented on GitHub (Dec 14, 2023): 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.
Author
Owner

@max06 commented on GitHub (Dec 14, 2023):

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.

@max06 commented on GitHub (Dec 14, 2023): There you go! ```text 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.
Author
Owner

@mlsmaycon commented on GitHub (Dec 14, 2023):

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

@mlsmaycon commented on GitHub (Dec 14, 2023): @max06 I missed some of the startup logs. Can you get the full log from management?
Author
Owner

@max06 commented on GitHub (Dec 14, 2023):

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.

@max06 commented on GitHub (Dec 14, 2023): Whoops, sorry. Yes, sure. ```text 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.
Author
Owner

@mlsmaycon commented on GitHub (Dec 14, 2023):

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

@mlsmaycon commented on GitHub (Dec 14, 2023): 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
Author
Owner

@vesper1978 commented on GitHub (Apr 23, 2025):

What's the status of this? A 10 second timeout that can't be adjusted is not good. Are we able to get it so that the timeout can be adjusted in the docker-compose.yml? I can't use keycloak as an IDP because it takes longer than 10 seconds.

@vesper1978 commented on GitHub (Apr 23, 2025): What's the status of this? A 10 second timeout that can't be adjusted is not good. Are we able to get it so that the timeout can be adjusted in the docker-compose.yml? I can't use keycloak as an IDP because it takes longer than 10 seconds.
Author
Owner

@alexanderbattig commented on GitHub (Jul 29, 2025):

Hi, I would also be interested in the status here, as the low timeout is actively blocking us from using Netbird. Making the timeout configurable would be highly appreciated.

@alexanderbattig commented on GitHub (Jul 29, 2025): Hi, I would also be interested in the status here, as the low timeout is actively blocking us from using Netbird. Making the timeout configurable would be highly appreciated.
Author
Owner

@ressys1978 commented on GitHub (Oct 14, 2025):

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: keycloak/keycloak#19342

Is there any update on this? I've had to resort to manually compiling the management service with an increased timeout.

@ressys1978 commented on GitHub (Oct 14, 2025): > Thanks, [@max06](https://github.com/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: [keycloak/keycloak#19342](https://github.com/keycloak/keycloak/pull/19342) Is there any update on this? I've had to resort to manually compiling the management service with an increased timeout.
Sign in to join this conversation.
1 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: SVI/netbird#544