SVI/netbird
1
0
Fork 0
mirror of https://github.com/netbirdio/netbird.git synced 2026-08-04 11:45:09 -04:00
Code Issues 3.0k Packages Projects Releases 10 Wiki Activity

[critical bug] Calling the API with a not existing user causes the system to become too slow #579

New Issue
Open
opened 2025-11-20 05:14:05 -05:00 by saavagebueno · 0 comments
saavagebueno commented 2025-11-20 05:14:05 -05:00
Owner
Copy Link

Originally created by @MohammedNoureldin on GitHub (Jan 12, 2024).

Describe the problem
In self-hosted Netbird, as soon as I try to call the API of Netbird using an access token issued by my Identity Provider a service account, the whole system starts to be horribly slow.

To Reproduce
Steps to reproduce the behavior:

  1. In the Identity Provider, e.g. KeyCloak, create a client named "netbird-backend" that enables service account. Actually this user is probably already there because it is part of setting Netbird up.
  2. Request an access token from the IdP:
token_response=$(curl -X POST -H "Content-Type: application/x-www-form-urlencoded" -d "client_id=netbird-backend&client_secret=$netbird_backend_service_user_secret&grant_type=client_credentials&scope=openid" $netbird_oidc_device_authorization_token_endpoint)

access_token=$(echo $token_response | jq -r '.access_token')
  1. Use that access token to call Netbird API:
users=$(curl -X GET https://$netbird_management_subdomain.$domain_name/api/users -H "Authorization: Bearer $access_token")

This will return 401 because the user created implicitly by KeyCloak for the service account client is not being found by Netbird. This is an issue/ a missing feature is reported here https://github.com/netbirdio/netbird/issues/1462. Anyway, after getting this 401, the whole system becomes too slow because of some caching error that arises after this API call.

Expected behavior
The system should not be affected by any invalid API calls.

NetBird status -d output:

logs of management:

2024-01-12T10:39:35Z INFO management/server/account.go:1543: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2024-01-12T10:39:35Z DEBG management/server/file_store.go:275: acquiring global lock
2024-01-12T10:39:35Z DEBG management/server/file_store.go:285: took 640ns to acquire global lock
2024-01-12T10:39:35Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore
2024-01-12T10:39:35Z DEBG management/server/account.go:1213: looking up user ce277538-2213-4ec5-bb96-4a4aedfa969c of account cmghd4oj5m1c73dihv1g in cache
2024-01-12T10:39:35Z DEBG management/server/account.go:1289: cache doesn't know about ce277538-2213-4ec5-bb96-4a4aedfa969c user
2024-01-12T10:39:35Z DEBG management/server/account.go:1294: cache doesn't know about 1 users from store, reloading
2024-01-12T10:39:35Z DEBG management/server/account.go:1151: account cmghd4oj5m1c73dihv1g not found in cache, reloading
2024-01-12T10:39:36Z DEBG management/server/account.go:1163: 4 entries received from IdP management
2024-01-12T10:39:36Z WARN management/server/account.go:1177: user ce277538-2213-4ec5-bb96-4a4aedfa969c not found in IDP
2024-01-12T10:39:36Z DEBG management/server/account.go:1151: account cmghd4oj5m1c73dihv1g not found in cache, reloading
2024-01-12T10:39:36Z DEBG management/server/account.go:1163: 4 entries received from IdP management
2024-01-12T10:39:36Z WARN management/server/account.go:1177: user ce277538-2213-4ec5-bb96-4a4aedfa969c not found in IDP
2024-01-12T10:39:36Z DEBG management/server/file_store.go:281: released global lock in 1.573880277s
2024-01-12T10:39:36Z DEBG management/server/account.go:1213: looking up user ce277538-2213-4ec5-bb96-4a4aedfa969c of account cmghd4oj5m1c73dihv1g in cache
2024-01-12T10:39:36Z DEBG management/server/account.go:1289: cache doesn't know about ce277538-2213-4ec5-bb96-4a4aedfa969c user
2024-01-12T10:39:36Z DEBG management/server/account.go:1294: cache doesn't know about 1 users from store, reloading
2024-01-12T10:39:36Z DEBG management/server/account.go:1151: account cmghd4oj5m1c73dihv1g not found in cache, reloading
2024-01-12T10:39:37Z DEBG management/server/account.go:1163: 4 entries received from IdP management
2024-01-12T10:39:37Z WARN management/server/account.go:1177: user ce277538-2213-4ec5-bb96-4a4aedfa969c not found in IDP
2024-01-12T10:39:37Z ERRO management/server/http/middleware/auth_middleware.go:82: Error when validating JWT claims: user ce277538-2213-4ec5-bb96-4a4aedfa969c not found in the IdP
2024-01-12T10:39:37Z ERRO management/server/http/util/util.go:80: got a handler error: token invalid
2024-01-12T10:39:37Z ERRO management/server/telemetry/http_api_metrics.go:181: HTTP response 3720184415: GET /api/users status 401
2024-01-12T10:39:37Z DEBG management/server/telemetry/http_api_metrics.go:201: request GET /api/users took 2211 ms and finished with status 401
.
.
.
2024-01-12T14:01:17Z DEBG management/server/account.go:1163: 4 entries received from IdP management
2024-01-12T14:01:17Z WARN management/server/account.go:1177: user ce277538-2213-4ec5-bb96-4a4aedfa969c not found in IDP
2024-01-12T14:01:17Z INFO management/server/account.go:1543: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2024-01-12T14:01:17Z DEBG management/server/file_store.go:275: acquiring global lock
2024-01-12T14:01:17Z DEBG management/server/file_store.go:285: took 840ns to acquire global lock
2024-01-12T14:01:17Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore
2024-01-12T14:01:17Z DEBG management/server/account.go:1213: looking up user d09f60c6-fb9f-4db8-a0ec-e610a3d2ec74 of account cmgio1oj5m1c73f3cl50 in cache
2024-01-12T14:01:17Z DEBG management/server/account.go:1289: cache doesn't know about ce277538-2213-4ec5-bb96-4a4aedfa969c user
2024-01-12T14:01:17Z DEBG management/server/account.go:1294: cache doesn't know about 1 users from store, reloading
2024-01-12T14:01:17Z DEBG management/server/account.go:1151: account cmgio1oj5m1c73f3cl50 not found in cache, reloading
2024-01-12T14:01:17Z DEBG management/server/idp/keycloak.go:125: requesting new jwt token for keycloak idp manager
2024-01-12T14:01:18Z DEBG management/server/account.go:1163: 4 entries received from IdP management
2024-01-12T14:01:18Z WARN management/server/account.go:1177: user ce277538-2213-4ec5-bb96-4a4aedfa969c not found in IDP
2024-01-12T14:01:18Z DEBG management/server/account.go:1132: skipping IDP App Meta update because accountID cmgio1oj5m1c73f3cl50 has been already set for user d09f60c6-fb9f-4db8-a0ec-e610a3d2ec74
2024-01-12T14:01:18Z DEBG management/server/file_store.go:281: released global lock in 836.569741ms
2024-01-12T14:01:18Z DEBG management/server/account.go:1213: looking up user d09f60c6-fb9f-4db8-a0ec-e610a3d2ec74 of account cmgio1oj5m1c73f3cl50 in cache
2024-01-12T14:01:18Z DEBG management/server/account.go:1289: cache doesn't know about ce277538-2213-4ec5-bb96-4a4aedfa969c user
2024-01-12T14:01:18Z DEBG management/server/account.go:1294: cache doesn't know about 1 users from store, reloading
2024-01-12T14:01:18Z DEBG management/server/account.go:1151: account cmgio1oj5m1c73f3cl50 not found in cache, reloading
2024-01-12T14:01:19Z DEBG management/server/account.go:1163: 4 entries received from IdP management
2024-01-12T14:01:19Z WARN management/server/account.go:1177: user ce277538-2213-4ec5-bb96-4a4aedfa969c not found in IDP
2024-01-12T14:01:19Z DEBG management/server/file_store.go:295: acquiring lock for account cmgio1oj5m1c73f3cl50
2024-01-12T14:01:19Z DEBG management/server/file_store.go:303: released lock for account cmgio1oj5m1c73f3cl50 in 19.48µs
2024-01-12T14:01:19Z INFO management/server/account.go:1543: overriding JWT Domain and DomainCategory claims since single account mode is enabled
2024-01-12T14:01:19Z DEBG management/server/file_store.go:275: acquiring global lock
2024-01-12T14:01:19Z DEBG management/server/file_store.go:285: took 720ns to acquire global lock
2024-01-12T14:01:19Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore
2024-01-12T14:01:19Z DEBG management/server/account.go:1213: looking up user d09f60c6-fb9f-4db8-a0ec-e610a3d2ec74 of account cmgio1oj5m1c73f3cl50 in cache
2024-01-12T14:01:19Z DEBG management/server/account.go:1289: cache doesn't know about ce277538-2213-4ec5-bb96-4a4aedfa969c user
2024-01-12T14:01:19Z DEBG management/server/account.go:1294: cache doesn't know about 1 users from store, reloading
2024-01-12T14:01:19Z DEBG management/server/account.go:1151: account cmgio1oj5m1c73f3cl50 not found in cache, reloading
2024-01-12T14:01:19Z DEBG management/server/account.go:1163: 4 entries received from IdP management
2024-01-12T14:01:19Z WARN management/server/account.go:1177: user ce277538-2213-4ec5-bb96-4a4aedfa969c not found in IDP
2024-01-12T14:01:19Z DEBG management/server/account.go:1132: skipping IDP App Meta update because accountID cmgio1oj5m1c73f3cl50 has been already set for user d09f60c6-fb9f-4db8-a0ec-e610a3d2ec74
2024-01-12T14:01:19Z DEBG management/server/file_store.go:281: released global lock in 581.50379ms
2024-01-12T14:01:19Z DEBG management/server/account.go:1213: looking up user d09f60c6-fb9f-4db8-a0ec-e610a3d2ec74 of account cmgio1oj5m1c73f3cl50 in cache
2024-01-12T14:01:19Z DEBG management/server/account.go:1289: cache doesn't know about ce277538-2213-4ec5-bb96-4a4aedfa969c user
2024-01-12T14:01:19Z DEBG management/server/account.go:1294: cache doesn't know about 1 users from store, reloading
2024-01-12T14:01:19Z DEBG management/server/account.go:1151: account cmgio1oj5m1c73f3cl50 not found in cache, reloading
2024-01-12T14:01:20Z DEBG management/server/account.go:1163: 4 entries received from IdP management
2024-01-12T14:01:20Z WARN management/server/account.go:1177: user ce277538-2213-4ec5-bb96-4a4aedfa969c not found in IDP
2024-01-12T14:01:20Z DEBG management/server/file_store.go:295: acquiring lock for account cmgio1oj5m1c73f3cl50
2024-01-12T14:01:20Z DEBG management/server/file_store.go:303: released lock for account cmgio1oj5m1c73f3cl50 in 21.72µs
2024-01-12T14:01:20Z DEBG management/server/telemetry/http_api_metrics.go:201: request GET /api/routes took 5011 ms and finished with status 200
.
.
The same logs get repeated many times before the page is finally accessed after a long wait...
. 
.
Originally created by @MohammedNoureldin on GitHub (Jan 12, 2024). **Describe the problem** In self-hosted Netbird, as soon as I try to call the API of Netbird using an access token issued by my Identity Provider a service account, the whole system starts to be horribly slow. **To Reproduce** Steps to reproduce the behavior: 1. In the Identity Provider, e.g. KeyCloak, create a client named "netbird-backend" that enables service account. Actually this user is probably already there because it is part of setting Netbird up. 2. Request an access token from the IdP: ``` token_response=$(curl -X POST -H "Content-Type: application/x-www-form-urlencoded" -d "client_id=netbird-backend&client_secret=$netbird_backend_service_user_secret&grant_type=client_credentials&scope=openid" $netbird_oidc_device_authorization_token_endpoint) access_token=$(echo $token_response | jq -r '.access_token') ``` 3. Use that access token to call Netbird API: ``` users=$(curl -X GET https://$netbird_management_subdomain.$domain_name/api/users -H "Authorization: Bearer $access_token") ``` This will return 401 because the user created implicitly by KeyCloak for the service account client is not being found by Netbird. This is an issue/ a missing feature is reported here https://github.com/netbirdio/netbird/issues/1462. Anyway, after getting this 401, the whole system becomes too slow because of some caching error that arises after this API call. **Expected behavior** The system should not be affected by any invalid API calls. **NetBird status -d output:** logs of management: ``` 2024-01-12T10:39:35Z INFO management/server/account.go:1543: overriding JWT Domain and DomainCategory claims since single account mode is enabled 2024-01-12T10:39:35Z DEBG management/server/file_store.go:275: acquiring global lock 2024-01-12T10:39:35Z DEBG management/server/file_store.go:285: took 640ns to acquire global lock 2024-01-12T10:39:35Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore 2024-01-12T10:39:35Z DEBG management/server/account.go:1213: looking up user ce277538-2213-4ec5-bb96-4a4aedfa969c of account cmghd4oj5m1c73dihv1g in cache 2024-01-12T10:39:35Z DEBG management/server/account.go:1289: cache doesn't know about ce277538-2213-4ec5-bb96-4a4aedfa969c user 2024-01-12T10:39:35Z DEBG management/server/account.go:1294: cache doesn't know about 1 users from store, reloading 2024-01-12T10:39:35Z DEBG management/server/account.go:1151: account cmghd4oj5m1c73dihv1g not found in cache, reloading 2024-01-12T10:39:36Z DEBG management/server/account.go:1163: 4 entries received from IdP management 2024-01-12T10:39:36Z WARN management/server/account.go:1177: user ce277538-2213-4ec5-bb96-4a4aedfa969c not found in IDP 2024-01-12T10:39:36Z DEBG management/server/account.go:1151: account cmghd4oj5m1c73dihv1g not found in cache, reloading 2024-01-12T10:39:36Z DEBG management/server/account.go:1163: 4 entries received from IdP management 2024-01-12T10:39:36Z WARN management/server/account.go:1177: user ce277538-2213-4ec5-bb96-4a4aedfa969c not found in IDP 2024-01-12T10:39:36Z DEBG management/server/file_store.go:281: released global lock in 1.573880277s 2024-01-12T10:39:36Z DEBG management/server/account.go:1213: looking up user ce277538-2213-4ec5-bb96-4a4aedfa969c of account cmghd4oj5m1c73dihv1g in cache 2024-01-12T10:39:36Z DEBG management/server/account.go:1289: cache doesn't know about ce277538-2213-4ec5-bb96-4a4aedfa969c user 2024-01-12T10:39:36Z DEBG management/server/account.go:1294: cache doesn't know about 1 users from store, reloading 2024-01-12T10:39:36Z DEBG management/server/account.go:1151: account cmghd4oj5m1c73dihv1g not found in cache, reloading 2024-01-12T10:39:37Z DEBG management/server/account.go:1163: 4 entries received from IdP management 2024-01-12T10:39:37Z WARN management/server/account.go:1177: user ce277538-2213-4ec5-bb96-4a4aedfa969c not found in IDP 2024-01-12T10:39:37Z ERRO management/server/http/middleware/auth_middleware.go:82: Error when validating JWT claims: user ce277538-2213-4ec5-bb96-4a4aedfa969c not found in the IdP 2024-01-12T10:39:37Z ERRO management/server/http/util/util.go:80: got a handler error: token invalid 2024-01-12T10:39:37Z ERRO management/server/telemetry/http_api_metrics.go:181: HTTP response 3720184415: GET /api/users status 401 2024-01-12T10:39:37Z DEBG management/server/telemetry/http_api_metrics.go:201: request GET /api/users took 2211 ms and finished with status 401 . . . 2024-01-12T14:01:17Z DEBG management/server/account.go:1163: 4 entries received from IdP management 2024-01-12T14:01:17Z WARN management/server/account.go:1177: user ce277538-2213-4ec5-bb96-4a4aedfa969c not found in IDP 2024-01-12T14:01:17Z INFO management/server/account.go:1543: overriding JWT Domain and DomainCategory claims since single account mode is enabled 2024-01-12T14:01:17Z DEBG management/server/file_store.go:275: acquiring global lock 2024-01-12T14:01:17Z DEBG management/server/file_store.go:285: took 840ns to acquire global lock 2024-01-12T14:01:17Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore 2024-01-12T14:01:17Z DEBG management/server/account.go:1213: looking up user d09f60c6-fb9f-4db8-a0ec-e610a3d2ec74 of account cmgio1oj5m1c73f3cl50 in cache 2024-01-12T14:01:17Z DEBG management/server/account.go:1289: cache doesn't know about ce277538-2213-4ec5-bb96-4a4aedfa969c user 2024-01-12T14:01:17Z DEBG management/server/account.go:1294: cache doesn't know about 1 users from store, reloading 2024-01-12T14:01:17Z DEBG management/server/account.go:1151: account cmgio1oj5m1c73f3cl50 not found in cache, reloading 2024-01-12T14:01:17Z DEBG management/server/idp/keycloak.go:125: requesting new jwt token for keycloak idp manager 2024-01-12T14:01:18Z DEBG management/server/account.go:1163: 4 entries received from IdP management 2024-01-12T14:01:18Z WARN management/server/account.go:1177: user ce277538-2213-4ec5-bb96-4a4aedfa969c not found in IDP 2024-01-12T14:01:18Z DEBG management/server/account.go:1132: skipping IDP App Meta update because accountID cmgio1oj5m1c73f3cl50 has been already set for user d09f60c6-fb9f-4db8-a0ec-e610a3d2ec74 2024-01-12T14:01:18Z DEBG management/server/file_store.go:281: released global lock in 836.569741ms 2024-01-12T14:01:18Z DEBG management/server/account.go:1213: looking up user d09f60c6-fb9f-4db8-a0ec-e610a3d2ec74 of account cmgio1oj5m1c73f3cl50 in cache 2024-01-12T14:01:18Z DEBG management/server/account.go:1289: cache doesn't know about ce277538-2213-4ec5-bb96-4a4aedfa969c user 2024-01-12T14:01:18Z DEBG management/server/account.go:1294: cache doesn't know about 1 users from store, reloading 2024-01-12T14:01:18Z DEBG management/server/account.go:1151: account cmgio1oj5m1c73f3cl50 not found in cache, reloading 2024-01-12T14:01:19Z DEBG management/server/account.go:1163: 4 entries received from IdP management 2024-01-12T14:01:19Z WARN management/server/account.go:1177: user ce277538-2213-4ec5-bb96-4a4aedfa969c not found in IDP 2024-01-12T14:01:19Z DEBG management/server/file_store.go:295: acquiring lock for account cmgio1oj5m1c73f3cl50 2024-01-12T14:01:19Z DEBG management/server/file_store.go:303: released lock for account cmgio1oj5m1c73f3cl50 in 19.48µs 2024-01-12T14:01:19Z INFO management/server/account.go:1543: overriding JWT Domain and DomainCategory claims since single account mode is enabled 2024-01-12T14:01:19Z DEBG management/server/file_store.go:275: acquiring global lock 2024-01-12T14:01:19Z DEBG management/server/file_store.go:285: took 720ns to acquire global lock 2024-01-12T14:01:19Z DEBG management/server/file_store.go:269: took 0 ms to persist the FileStore 2024-01-12T14:01:19Z DEBG management/server/account.go:1213: looking up user d09f60c6-fb9f-4db8-a0ec-e610a3d2ec74 of account cmgio1oj5m1c73f3cl50 in cache 2024-01-12T14:01:19Z DEBG management/server/account.go:1289: cache doesn't know about ce277538-2213-4ec5-bb96-4a4aedfa969c user 2024-01-12T14:01:19Z DEBG management/server/account.go:1294: cache doesn't know about 1 users from store, reloading 2024-01-12T14:01:19Z DEBG management/server/account.go:1151: account cmgio1oj5m1c73f3cl50 not found in cache, reloading 2024-01-12T14:01:19Z DEBG management/server/account.go:1163: 4 entries received from IdP management 2024-01-12T14:01:19Z WARN management/server/account.go:1177: user ce277538-2213-4ec5-bb96-4a4aedfa969c not found in IDP 2024-01-12T14:01:19Z DEBG management/server/account.go:1132: skipping IDP App Meta update because accountID cmgio1oj5m1c73f3cl50 has been already set for user d09f60c6-fb9f-4db8-a0ec-e610a3d2ec74 2024-01-12T14:01:19Z DEBG management/server/file_store.go:281: released global lock in 581.50379ms 2024-01-12T14:01:19Z DEBG management/server/account.go:1213: looking up user d09f60c6-fb9f-4db8-a0ec-e610a3d2ec74 of account cmgio1oj5m1c73f3cl50 in cache 2024-01-12T14:01:19Z DEBG management/server/account.go:1289: cache doesn't know about ce277538-2213-4ec5-bb96-4a4aedfa969c user 2024-01-12T14:01:19Z DEBG management/server/account.go:1294: cache doesn't know about 1 users from store, reloading 2024-01-12T14:01:19Z DEBG management/server/account.go:1151: account cmgio1oj5m1c73f3cl50 not found in cache, reloading 2024-01-12T14:01:20Z DEBG management/server/account.go:1163: 4 entries received from IdP management 2024-01-12T14:01:20Z WARN management/server/account.go:1177: user ce277538-2213-4ec5-bb96-4a4aedfa969c not found in IDP 2024-01-12T14:01:20Z DEBG management/server/file_store.go:295: acquiring lock for account cmgio1oj5m1c73f3cl50 2024-01-12T14:01:20Z DEBG management/server/file_store.go:303: released lock for account cmgio1oj5m1c73f3cl50 in 21.72µs 2024-01-12T14:01:20Z DEBG management/server/telemetry/http_api_metrics.go:201: request GET /api/routes took 5011 ms and finished with status 200 . . The same logs get repeated many times before the page is finally accessed after a long wait... . . ```
saavagebueno added the bugmanagement-serviceidpconfig-idp labels 2025-11-20 05:14:05 -05:00
Sign in to join this conversation.
No Branch/Tag Specified
Branches Tags
Labels
Clear labels
2021 Q4
2022 Q1
2022 Q1
accessibility
acl
agent
agent
Android
Android
api
authentik
automation
azure
battery-usage
bug
cache
client
client-ui
cloud
cloud-only
cloudflare
community
compatibility
config-idp
config-issue
connection
contribution
coturn
cross-vpn
dashboard
data-usage
distribution
dns
docker
documentation
duplicate
enhancement
enhancement
event-stream
feature-request
freebsd
getting-started
go
good first issue
gui
help wanted
home-assistant
idp
inconsistency
integration
integrations
ios
ipv6
jwt
k8s
keycloak
linux
login
macos
management-service
missing-docs
mobile
moved-internal
needs-review
netbird-ui
networking
new-platform
nginx
notification
okta
openwrt
packaging
peer-management
peer-management
peer-management
performance
postgres
posture-checks
psk
pull-request
Mirrored from GitHub Pull Request
 question
refactor
relay
release
rfc
routes
security
security-related
self-hosting
server
signal
sleep-issue
ssh
ssl
status
store
synology
system-compatibility-issue
test-suite
third-party-integration
triage
triage-needed
troubleshooting
UX
waiting-feedback
windows
wontfix
zitadel
No Label bug config-idp idp management-service
Milestone
No items
No Milestone
Projects
Clear projects
No project
Assignees
Clear assignees
saavagebueno
No Assignees
1 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: SVI/netbird#579
Delete Branch "%!s()"

Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?