Refresh tokens not working

[rizlas]

I'm currently using VW+Keycloak with sso_auth_only_not_session set to false. In KC access token life span is set to 30 minutes and refresh tokens are enabled.

Despite various tests, the bitwarden extension session expires after 30 minutes. It seems that the refresh tokens are not working. What could I check?

Here's a screenshot of KC

Your environment (Generated via diagnostics page)

• Vaultwarden version: v1.30.5-3
• Web-vault version: voidc_button-v2024.1.2-6
• OS/Arch: linux/x86_64
• Running within a container: true (Base: Debian)
• Environment settings overridden: false
• Uses a reverse proxy: true
• IP Header check: true (X-Real-IP)
• Internet access: true
• Internet access via a proxy: false
• DNS Check: true
• Browser/Server Time Check: true
• Server/NTP Time Check: true
• Domain Configuration Check: true
• HTTPS Check: true
• Database type: PostgreSQL
• Database version: PostgreSQL 16.2 on x86_64-pc-linux-gnu, compiled by gcc (Debian 12.2.0-14) 12.2.0, 64-bit
• Clients used:
• Reverse proxy and version:
• Other relevant information:

Config (Generated via diagnostics page)

Show Running Config

**Environment settings which are overridden:** ```json { "_duo_akey": null, "_enable_duo": true, "_enable_email_2fa": true, "_enable_smtp": true, "_enable_yubico": true, "_icon_service_csp": "", "_icon_service_url": "", "_ip_header_enabled": true, "_smtp_img_src": "cid:", "admin_ratelimit_max_burst": 3, "admin_ratelimit_seconds": 300, "admin_session_lifetime": 20, "admin_token": "***", "allowed_iframe_ancestors": "", "attachments_folder": "data/attachments", "auth_request_purge_schedule": "30 * * * * *", "authenticator_disable_time_drift": false, "data_folder": "data", "database_conn_init": "", "database_max_conns": 10, "database_timeout": 30, "database_url": "**********://**************************************************", "db_connection_retries": 15, "disable_2fa_remember": false, "disable_admin_token": false, "disable_icon_download": false, "domain": "*****://********************", "domain_origin": "*****://********************", "domain_path": "", "domain_set": true, "duo_host": null, "duo_ikey": null, "duo_skey": null, "email_attempts_limit": 3, "email_change_allowed": false, "email_expiration_time": 600, "email_token_size": 6, "emergency_access_allowed": true, "emergency_notification_reminder_schedule": "0 3 * * * *", "emergency_request_timeout_schedule": "0 7 * * * *", "enable_db_wal": true, "event_cleanup_schedule": "0 10 0 * * *", "events_days_retain": 90, "experimental_client_feature_flags": "fido2-vault-credentials", "extended_logging": true, "helo_name": "********************", "hibp_api_key": null, "icon_blacklist_non_global_ips": true, "icon_blacklist_regex": null, "icon_cache_folder": "data/icon_cache", "icon_cache_negttl": 259200, "icon_cache_ttl": 2592000, "icon_download_timeout": 10, "icon_redirect_code": 302, "icon_service": "internal", "incomplete_2fa_schedule": "30 * * * * *", "incomplete_2fa_time_limit": 3, "invitation_expiration_hours": 24, "invitation_org_name": "****** ******", "invitations_allowed": true, "ip_header": "X-Real-IP", "job_poll_interval_ms": 30000, "log_file": null, "log_level": "info", "log_level_override": "", "log_timestamp_format": "%Y-%m-%d %H:%M:%S.%3f", "login_ratelimit_max_burst": 10, "login_ratelimit_seconds": 60, "org_attachment_limit": null, "org_creation_users": "***************************,********************,*********************,************************", "org_events_enabled": true, "org_groups_enabled": true, "password_hints_allowed": true, "password_iterations": 600000, "purge_incomplete_sso_nonce": "0 20 0 * * *", "push_enabled": true, "push_identity_uri": "https://identity.bitwarden.com", "push_installation_id": "***", "push_installation_key": "***", "push_relay_uri": "https://push.bitwarden.com", "reload_templates": false, "require_device_email": false, "rsa_key_filename": "data/rsa_key", "send_purge_schedule": "0 5 * * * *", "sendmail_command": null, "sends_allowed": true, "sends_folder": "data/sends", "show_password_hint": false, "signups_allowed": false, "signups_domains_whitelist": "", "signups_verify": true, "signups_verify_resend_limit": 6, "signups_verify_resend_time": 1800, "smtp_accept_invalid_certs": false, "smtp_accept_invalid_hostnames": false, "smtp_auth_mechanism": null, "smtp_debug": false, "smtp_embed_images": true, "smtp_explicit_tls": null, "smtp_from": "****************", "smtp_from_name": "****** ******", "smtp_host": "**********************", "smtp_password": "***", "smtp_port": 25, "smtp_security": "starttls", "smtp_ssl": null, "smtp_timeout": 15, "smtp_username": "***********", "sso_audience_trusted": null, "sso_auth_only_not_session": false, "sso_authority": "https://******.******/auth/realms/******", "sso_authorize_extra_params": "", "sso_callback_path": "https://******.******/identity/connect/oidc-signin", "sso_client_cache_expiration": 0, "sso_client_id": "******.******", "sso_client_secret": "***", "sso_debug_tokens": false, "sso_enabled": true, "sso_experimental_no_master_pwd": false, "sso_master_password_policy": "{\"enforceOnLogin\":false,\"minComplexity\":3,\"minLength\":12,\"requireLower\":true,\"requireNumbers\":true,\"requireSpecial\":true,\"requireUpper\":true}", "sso_only": true, "sso_organizations_invite": false, "sso_organizations_token_path": "/groups", "sso_pkce": true, "sso_roles_default_to_user": true, "sso_roles_enabled": false, "sso_roles_token_path": "/resource_access/******.******/roles", "sso_scopes": "email profile", "sso_signups_match_email": true, "templates_folder": "/it_lang_templates", "tmp_folder": "data/tmp", "trash_auto_delete_days": 90, "trash_purge_schedule": "0 5 0 * * *", "use_sendmail": false, "use_syslog": false, "user_attachment_limit": 100000, "user_send_limit": null, "web_vault_enabled": true, "web_vault_folder": "web-vault/", "websocket_address": "0.0.0.0", "websocket_enabled": false, "websocket_port": 3012, "yubico_client_id": null, "yubico_secret_key": null, "yubico_server": null } ```

[Timshel]

Hey,

I would start by updating to 1.30.5-7 even if I doubt it will change much. Then you can activate SSO_DEBUG_TOKENS to check the returned token from KC.

And if you open the network debug panel of your browser you should be able to check the Vaultwarden refresh and access token and decode them using https://jwt.io to check the expiration times.

[rizlas]

1.30.5-3 is the latest docker tags available on docker hub.

I enabled SSO_DEBUG_TOKENS, both access and refresh tokens are issued. Access token expiration is set to 30 min, refresh token to 9h (?).

Example:

• Access token exp: Apr 15 2024 09:24
• Refresh token exp: Apr 15 2024 18:43

After 09:24 I'll be logged out.

[Timshel]

I managed to recover timshel on dockerhub so it's released here now : https://hub.docker.com/r/timshel/vaultwarden/tags

If you are logged out at 09:24 it probably means a refresh call failed, can you share the server log and check the network log in your browser ?

[rizlas]

Yes, I'll set the access token to a lower value and enable debug log for VW. Thank you

[Timshel]

6min is usually the lowest you can go afterward you'll hit bugs if the issued access token is considered as immediately expired by Bitwarden.

[rizlas]

Access token set to 6 min. Here relevant logs. Notice the error at the end.

[2024-04-15 12:02:58.310][h2::client][DEBUG] binding client connection
[2024-04-15 12:02:58.310][h2::client][DEBUG] client connection bound
[2024-04-15 12:02:58.310][h2::codec::framed_write][DEBUG] send frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
[2024-04-15 12:02:58.310][h2::proto::connection][DEBUG] Connection; peer=Client
[2024-04-15 12:02:58.310][h2::codec::framed_write][DEBUG] send frame=WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 }
[2024-04-15 12:02:58.310][h2::codec::framed_write][DEBUG] send frame=Headers { stream_id: StreamId(1), flags: (0x5: END_HEADERS | END_STREAM) }
[2024-04-15 12:02:58.310][h2::codec::framed_read][DEBUG] received frame=Settings { flags: (0x0), max_concurrent_streams: 128, initial_window_size: 65536, max_frame_size: 16777215 }
[2024-04-15 12:02:58.310][h2::codec::framed_write][DEBUG] send frame=Settings { flags: (0x1: ACK) }
[2024-04-15 12:02:58.310][h2::codec::framed_read][DEBUG] received frame=WindowUpdate { stream_id: StreamId(0), size_increment: 2147418112 }
[2024-04-15 12:02:58.311][h2::codec::framed_read][DEBUG] received frame=Settings { flags: (0x1: ACK) }
[2024-04-15 12:02:58.311][h2::proto::settings][DEBUG] received settings ACK; applying Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
[2024-04-15 12:02:58.329][h2::codec::framed_read][DEBUG] received frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
[2024-04-15 12:02:58.329][h2::codec::framed_read][DEBUG] received frame=Data { stream_id: StreamId(1) }
[2024-04-15 12:02:58.329][h2::codec::framed_read][DEBUG] received frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }
[2024-04-15 12:02:58.329][hickory_proto::xfer::dns_exchange][DEBUG] io_stream is done, shutting down
[2024-04-15 12:02:58.329][h2::codec::framed_write][DEBUG] send frame=GoAway { error_code: NO_ERROR, last_stream_id: StreamId(0) }
[2024-04-15 12:02:58.329][h2::proto::connection][DEBUG] Connection::poll; connection error error=GoAway(b"", NO_ERROR, Library)
[2024-04-15 12:02:58.329][vaultwarden::sso][DEBUG] Id token: eyJ**********cLqog
[2024-04-15 12:02:58.329][vaultwarden::sso][DEBUG] Access token: eyJhb*****************WJaQw
[2024-04-15 12:02:58.329][vaultwarden::sso][DEBUG] Refresh token: Some("eyJhbG*************************jVGKg")
[2024-04-15 12:02:58.329][vaultwarden::sso][DEBUG] Expiration time: Some(360s)
[2024-04-15 12:02:58.335][vaultwarden::sso][DEBUG] Refresh_payload: BasicTokenClaims { iat: Some(1713175378), nbf: None, exp: 1713208571 }
[2024-04-15 12:02:58.338][vaultwarden::api::identity][INFO] User ******** logged in successfully. IP: 1***********3

6 minutes Access token will expire at 12:08:58 12:15: Refresh browser

[2024-04-15 12:15:23.160][h2::client][DEBUG] binding client connection
[2024-04-15 12:15:23.160][h2::client][DEBUG] client connection bound
[2024-04-15 12:15:23.160][h2::codec::framed_write][DEBUG] send frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
[2024-04-15 12:15:23.160][h2::proto::connection][DEBUG] Connection; peer=Client
[2024-04-15 12:15:23.160][h2::codec::framed_write][DEBUG] send frame=WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 }
[2024-04-15 12:15:23.160][h2::codec::framed_write][DEBUG] send frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
[2024-04-15 12:15:23.160][h2::codec::framed_write][DEBUG] send frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }
[2024-04-15 12:15:23.161][h2::codec::framed_read][DEBUG] received frame=Settings { flags: (0x0), max_concurrent_streams: 128, initial_window_size: 65536, max_frame_size: 16777215 }
[2024-04-15 12:15:23.161][h2::codec::framed_write][DEBUG] send frame=Settings { flags: (0x1: ACK) }
[2024-04-15 12:15:23.161][h2::codec::framed_read][DEBUG] received frame=WindowUpdate { stream_id: StreamId(0), size_increment: 2147418112 }
[2024-04-15 12:15:23.161][h2::codec::framed_read][DEBUG] received frame=Settings { flags: (0x1: ACK) }
[2024-04-15 12:15:23.161][h2::proto::settings][DEBUG] received settings ACK; applying Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
[2024-04-15 12:15:23.161][h2::codec::framed_read][DEBUG] received frame=WindowUpdate { stream_id: StreamId(1), size_increment: 2147418111 }
[2024-04-15 12:15:23.187][h2::codec::framed_read][DEBUG] received frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
[2024-04-15 12:15:23.187][h2::codec::framed_read][DEBUG] received frame=Data { stream_id: StreamId(1) }
[2024-04-15 12:15:23.187][h2::codec::framed_read][DEBUG] received frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }
[2024-04-15 12:15:23.187][hickory_proto::xfer::dns_exchange][DEBUG] io_stream is done, shutting down
[2024-04-15 12:15:23.187][h2::codec::framed_write][DEBUG] send frame=GoAway { error_code: NO_ERROR, last_stream_id: StreamId(0) }
[2024-04-15 12:15:23.187][h2::proto::connection][DEBUG] Connection::poll; connection error error=GoAway(b"", NO_ERROR, Library)
[2024-04-15 12:15:23.187][vaultwarden::sso][DEBUG] Refresh_payload: BasicTokenClaims { iat: Some(1713176123), nbf: None, exp: 1713208571 }
[2024-04-15 12:15:23.192][response][INFO] (login) POST /identity/connect/token => 200 OK
[2024-04-15 12:15:24.780][request][INFO] POST /identity/connect/token

[2024-04-15 12:15:24.781][vaultwarden::auth][ERROR] Invalid refresh token
[2024-04-15 12:15:24.781][vaultwarden::api::identity][ERROR] {"ErrorModel":{"Message":"Invalid refresh token","Object":"error"},"ExceptionMessage":null,"ExceptionStackTrace":null,"InnerExceptionMessage":null,"Message":"Invalid refresh token","Object":"error","ValidationErrors":{"":["Invalid refresh token"]},"error":"","error_description":""}

[2024-04-15 12:15:24.781][response][INFO] (login) POST /identity/connect/token => 401 Unauthorized
[2024-04-15 12:15:25.327][request][INFO] GET /api/config
[2024-04-15 12:15:25.327][response][INFO] (config) GET /api/config => 200 OK
[2024-04-15 12:15:45.434][vaultwarden::api::core::accounts][DEBUG] Purging auth requests
[2024-04-15 12:15:45.434][vaultwarden::api::core::two_factor][DEBUG] Sending notifications for incomplete 2FA logins

[Timshel]

unless I'm nistaken you are not running 1.30.5-7 ?

[Timshel]

Can reproduce with latest anyway will check

[rizlas]

Yeah, I'm running 1.30.5-7

Good, thank you

[Timshel]

Ok I'm seeing as many as 4 refresh token call in parallel :( with the v2024.3.1-1 web vault client :(.

[rizlas]

Confirm, I'm using also that version of webvault

[tribut]

Seeing this too.

In my tests, the client is returning with a refresh_token which was valid earlier but has already been purged from the database.

[Timshel]

Just pushed 1.30.5-8 where I removed rolling the device token. Be aware it's on top of latest main and with the new web-vault version.

Should be available in ~1h.

[rizlas]

Thanks, I'll test it tomorrow

[rizlas]

LGTM I'll conduct further tests tomorrow

[rizlas]

Nothing else to add.. Thank you for the quick fix!