Timshel/vaultwarden

Invalid refresh token

Halyul opened this issue · 9 comments

Halyul commented

Subject of the issue

The client gets logged out after the expiry of access token while refresh token and offline access are enabled. Seems that vaultwarden is unable to connect to the sso and renew the access token using the refresh token. For some unknown reason, only mobile clients get logged out while the browser extension has no such a behaviour. Additionally, the mobile clients will prompt the account has already added sometimes at the login page and it seems that the vault can be decrypted with only master password without reauthenticating through sso to get a valid access token (see the second section of logs, which happened right after the end of the first section of logs).

Deployment environment

  • vaultwarden version: oidcwarden/vaultwarden-oidc:latest-alpine

  • Install method: docker

  • Clients used: android, ios

  • Reverse proxy and version: n/a

  • MySQL/MariaDB or PostgreSQL version: postgres:16-alpine

  • Other relevant details:

  • zitadel version: ghcr.io/zitadel/zitadel:latest
  • zitadel database version: postgres:16-alpine
  • vaultwarden envs:
DATABASE_URL
ADMIN_TOKEN
PASSWORD_HINTS_ALLOWED=false
YUBICO_CLIENT_ID
YUBICO_SECRET_KEY
EMAIL_CHANGE_ALLOWED=false
EXPERIMENTAL_CLIENT_FEATURE_FLAGS=fido2-vault-credentials,autofill-v2,autofill-overlay
PUSH_ENABLED=true
PUSH_INSTALLATION_ID
PUSH_INSTALLATION_KEY
SSO_ENABLED=true
SSO_ONLY=true
SSO_AUTHORITY
SSO_AUDIENCE_TRUSTED
SSO_CLIENT_ID
SSO_CLIENT_SECRET
SSO_SCOPES="email profile offline_access"
SSO_FRONTEND='override'
LOG_LEVEL=debug
SSO_DEBUG_TOKENS=true

Steps to reproduce

n/a

Expected behaviour

n/a

Actual behaviour

n/a

Troubleshooting data

[2024-02-25 05:51:52.366][request][INFO] POST /identity/connect/token
[2024-02-25 05:51:52.370][request][INFO] POST /identity/connect/token
[2024-02-25 05:51:52.496][reqwest::connect][DEBUG] starting new connection: https://zitadel.example.com/
[2024-02-25 05:51:52.501][h2::client][DEBUG] binding client connection
[2024-02-25 05:51:52.502][h2::client][DEBUG] client connection bound
[2024-02-25 05:51:52.502][h2::codec::framed_write][DEBUG] send frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
[2024-02-25 05:51:52.502][h2::proto::connection][DEBUG] Connection; peer=Client
[2024-02-25 05:51:52.502][h2::codec::framed_read][DEBUG] received frame=Settings { flags: (0x0), header_table_size: 4096, max_concurrent_streams: 250, initial_window_size: 1048576, max_frame_size: 1048576, max_header_list_size: 1048896 }
[2024-02-25 05:51:52.502][h2::codec::framed_write][DEBUG] send frame=Settings { flags: (0x1: ACK) }
[2024-02-25 05:51:52.502][h2::codec::framed_read][DEBUG] received frame=WindowUpdate { stream_id: StreamId(0), size_increment: 983041 }
[2024-02-25 05:51:52.502][h2::codec::framed_write][DEBUG] send frame=WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 }
[2024-02-25 05:51:52.502][h2::codec::framed_write][DEBUG] send frame=Headers { stream_id: StreamId(1), flags: (0x5: END_HEADERS | END_STREAM) }
[2024-02-25 05:51:52.503][h2::codec::framed_read][DEBUG] received frame=Settings { flags: (0x1: ACK) }
[2024-02-25 05:51:52.503][h2::proto::settings][DEBUG] received settings ACK; applying Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
[2024-02-25 05:51:52.503][reqwest::connect][DEBUG] starting new connection: https://zitadel.example.com/
[2024-02-25 05:51:52.507][h2::client][DEBUG] binding client connection
[2024-02-25 05:51:52.507][h2::client][DEBUG] client connection bound
[2024-02-25 05:51:52.507][h2::codec::framed_write][DEBUG] send frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
[2024-02-25 05:51:52.507][h2::proto::connection][DEBUG] Connection; peer=Client
[2024-02-25 05:51:52.508][h2::codec::framed_read][DEBUG] received frame=Settings { flags: (0x0), header_table_size: 4096, max_concurrent_streams: 250, initial_window_size: 1048576, max_frame_size: 1048576, max_header_list_size: 1048896 }
[2024-02-25 05:51:52.508][h2::codec::framed_write][DEBUG] send frame=Settings { flags: (0x1: ACK) }
[2024-02-25 05:51:52.508][h2::codec::framed_read][DEBUG] received frame=WindowUpdate { stream_id: StreamId(0), size_increment: 983041 }
[2024-02-25 05:51:52.508][h2::codec::framed_write][DEBUG] send frame=WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 }
[2024-02-25 05:51:52.508][h2::codec::framed_write][DEBUG] send frame=Headers { stream_id: StreamId(1), flags: (0x5: END_HEADERS | END_STREAM) }
[2024-02-25 05:51:52.508][h2::codec::framed_read][DEBUG] received frame=Settings { flags: (0x1: ACK) }
[2024-02-25 05:51:52.508][h2::proto::settings][DEBUG] received settings ACK; applying Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
[2024-02-25 05:51:52.517][h2::codec::framed_read][DEBUG] received frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
[2024-02-25 05:51:52.517][h2::codec::framed_read][DEBUG] received frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }
[2024-02-25 05:51:52.518][h2::codec::framed_write][DEBUG] send frame=GoAway { error_code: NO_ERROR, last_stream_id: StreamId(0) }
[2024-02-25 05:51:52.518][h2::proto::connection][DEBUG] Connection::poll; connection error error=GoAway(b"", NO_ERROR, Library)
[2024-02-25 05:51:52.520][h2::codec::framed_read][DEBUG] received frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
[2024-02-25 05:51:52.520][h2::codec::framed_read][DEBUG] received frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }
[2024-02-25 05:51:52.520][h2::codec::framed_write][DEBUG] send frame=GoAway { error_code: NO_ERROR, last_stream_id: StreamId(0) }
[2024-02-25 05:51:52.520][h2::proto::connection][DEBUG] Connection::poll; connection error error=GoAway(b"", NO_ERROR, Library)
[2024-02-25 05:51:52.578][reqwest::connect][DEBUG] starting new connection: https://zitadel.example.com/
[2024-02-25 05:51:52.579][reqwest::connect][DEBUG] starting new connection: https://zitadel.example.com/
[2024-02-25 05:51:52.581][h2::client][DEBUG] binding client connection
[2024-02-25 05:51:52.581][h2::client][DEBUG] client connection bound
[2024-02-25 05:51:52.581][h2::codec::framed_write][DEBUG] send frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
[2024-02-25 05:51:52.581][h2::proto::connection][DEBUG] Connection; peer=Client
[2024-02-25 05:51:52.582][h2::codec::framed_read][DEBUG] received frame=Settings { flags: (0x0), header_table_size: 4096, max_concurrent_streams: 250, initial_window_size: 1048576, max_frame_size: 1048576, max_header_list_size: 1048896 }
[2024-02-25 05:51:52.582][h2::codec::framed_write][DEBUG] send frame=Settings { flags: (0x1: ACK) }
[2024-02-25 05:51:52.582][h2::codec::framed_read][DEBUG] received frame=WindowUpdate { stream_id: StreamId(0), size_increment: 983041 }
[2024-02-25 05:51:52.582][h2::codec::framed_write][DEBUG] send frame=WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 }
[2024-02-25 05:51:52.582][h2::codec::framed_write][DEBUG] send frame=Headers { stream_id: StreamId(1), flags: (0x5: END_HEADERS | END_STREAM) }
[2024-02-25 05:51:52.582][h2::codec::framed_read][DEBUG] received frame=Settings { flags: (0x1: ACK) }
[2024-02-25 05:51:52.582][h2::proto::settings][DEBUG] received settings ACK; applying Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
[2024-02-25 05:51:52.583][h2::client][DEBUG] binding client connection
[2024-02-25 05:51:52.583][h2::client][DEBUG] client connection bound
[2024-02-25 05:51:52.583][h2::codec::framed_write][DEBUG] send frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
[2024-02-25 05:51:52.583][h2::proto::connection][DEBUG] Connection; peer=Client
[2024-02-25 05:51:52.583][h2::codec::framed_read][DEBUG] received frame=Settings { flags: (0x0), header_table_size: 4096, max_concurrent_streams: 250, initial_window_size: 1048576, max_frame_size: 1048576, max_header_list_size: 1048896 }
[2024-02-25 05:51:52.584][h2::codec::framed_write][DEBUG] send frame=Settings { flags: (0x1: ACK) }
[2024-02-25 05:51:52.584][h2::codec::framed_read][DEBUG] received frame=WindowUpdate { stream_id: StreamId(0), size_increment: 983041 }
[2024-02-25 05:51:52.584][h2::codec::framed_write][DEBUG] send frame=WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 }
[2024-02-25 05:51:52.584][h2::codec::framed_write][DEBUG] send frame=Headers { stream_id: StreamId(1), flags: (0x5: END_HEADERS | END_STREAM) }
[2024-02-25 05:51:52.584][h2::codec::framed_read][DEBUG] received frame=Settings { flags: (0x1: ACK) }
[2024-02-25 05:51:52.584][h2::proto::settings][DEBUG] received settings ACK; applying Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
[2024-02-25 05:51:52.592][h2::codec::framed_read][DEBUG] received frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
[2024-02-25 05:51:52.592][h2::codec::framed_read][DEBUG] received frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }
[2024-02-25 05:51:52.592][h2::codec::framed_write][DEBUG] send frame=GoAway { error_code: NO_ERROR, last_stream_id: StreamId(0) }
[2024-02-25 05:51:52.592][h2::proto::connection][DEBUG] Connection::poll; connection error error=GoAway(b"", NO_ERROR, Library)
[2024-02-25 05:51:52.594][h2::codec::framed_read][DEBUG] received frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
[2024-02-25 05:51:52.594][h2::codec::framed_read][DEBUG] received frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }
[2024-02-25 05:51:52.594][h2::codec::framed_write][DEBUG] send frame=GoAway { error_code: NO_ERROR, last_stream_id: StreamId(0) }
[2024-02-25 05:51:52.594][h2::proto::connection][DEBUG] Connection::poll; connection error error=GoAway(b"", NO_ERROR, Library)
[2024-02-25 05:51:52.654][reqwest::connect][DEBUG] starting new connection: https://zitadel.example.com/
[2024-02-25 05:51:52.656][reqwest::connect][DEBUG] starting new connection: https://zitadel.example.com/
[2024-02-25 05:51:52.657][h2::client][DEBUG] binding client connection
[2024-02-25 05:51:52.657][h2::client][DEBUG] client connection bound
[2024-02-25 05:51:52.657][h2::codec::framed_write][DEBUG] send frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
[2024-02-25 05:51:52.657][h2::proto::connection][DEBUG] Connection; peer=Client
[2024-02-25 05:51:52.658][h2::codec::framed_read][DEBUG] received frame=Settings { flags: (0x0), header_table_size: 4096, max_concurrent_streams: 250, initial_window_size: 1048576, max_frame_size: 1048576, max_header_list_size: 1048896 }
[2024-02-25 05:51:52.658][h2::codec::framed_write][DEBUG] send frame=Settings { flags: (0x1: ACK) }
[2024-02-25 05:51:52.658][h2::codec::framed_read][DEBUG] received frame=WindowUpdate { stream_id: StreamId(0), size_increment: 983041 }
[2024-02-25 05:51:52.658][h2::codec::framed_write][DEBUG] send frame=WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 }
[2024-02-25 05:51:52.658][h2::codec::framed_write][DEBUG] send frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
[2024-02-25 05:51:52.658][h2::codec::framed_write][DEBUG] send frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }
[2024-02-25 05:51:52.658][h2::codec::framed_read][DEBUG] received frame=Settings { flags: (0x1: ACK) }
[2024-02-25 05:51:52.658][h2::proto::settings][DEBUG] received settings ACK; applying Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
[2024-02-25 05:51:52.660][h2::client][DEBUG] binding client connection
[2024-02-25 05:51:52.660][h2::client][DEBUG] client connection bound
[2024-02-25 05:51:52.660][h2::codec::framed_write][DEBUG] send frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
[2024-02-25 05:51:52.660][h2::proto::connection][DEBUG] Connection; peer=Client
[2024-02-25 05:51:52.660][h2::codec::framed_read][DEBUG] received frame=Settings { flags: (0x0), header_table_size: 4096, max_concurrent_streams: 250, initial_window_size: 1048576, max_frame_size: 1048576, max_header_list_size: 1048896 }
[2024-02-25 05:51:52.660][h2::codec::framed_write][DEBUG] send frame=Settings { flags: (0x1: ACK) }
[2024-02-25 05:51:52.660][h2::codec::framed_read][DEBUG] received frame=WindowUpdate { stream_id: StreamId(0), size_increment: 983041 }
[2024-02-25 05:51:52.660][h2::codec::framed_write][DEBUG] send frame=WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 }
[2024-02-25 05:51:52.660][h2::codec::framed_write][DEBUG] send frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
[2024-02-25 05:51:52.660][h2::codec::framed_write][DEBUG] send frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }
[2024-02-25 05:51:52.660][h2::codec::framed_read][DEBUG] received frame=Settings { flags: (0x1: ACK) }
[2024-02-25 05:51:52.660][h2::proto::settings][DEBUG] received settings ACK; applying Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
[2024-02-25 05:51:52.811][request][INFO] POST /identity/connect/token
[2024-02-25 05:51:52.815][vaultwarden::auth][ERROR] Invalid refresh token
[2024-02-25 05:51:52.815][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-02-25 05:51:52.815][response][INFO] (login) POST /identity/connect/token => 401 Unauthorized
[2024-02-25 05:51:53.156][request][INFO] POST /identity/connect/token
[2024-02-25 05:51:53.156][vaultwarden::auth][ERROR] Invalid refresh token
[2024-02-25 05:51:53.157][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-02-25 05:51:53.157][response][INFO] (login) POST /identity/connect/token => 401 Unauthorized
[2024-02-25 05:51:53.271][request][INFO] GET /api/config/
[2024-02-25 05:51:53.271][response][INFO] (config) GET /api/config => 200 OK
[2024-02-25 05:51:53.391][request][INFO] GET /api/config/
[2024-02-25 05:51:53.391][response][INFO] (config) GET /api/config => 200 OK
[2024-02-25 05:51:53.504][request][INFO] GET /api/config/
[2024-02-25 05:51:53.504][response][INFO] (config) GET /api/config => 200 OK
[2024-02-25 05:51:53.545][request][INFO] GET /api/config/
[2024-02-25 05:51:53.545][response][INFO] (config) GET /api/config => 200 OK
[2024-02-25 05:51:53.622][h2::codec::framed_read][DEBUG] received frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
[2024-02-25 05:51:53.623][h2::codec::framed_read][DEBUG] received frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }
[2024-02-25 05:51:53.623][h2::codec::framed_write][DEBUG] send frame=GoAway { error_code: NO_ERROR, last_stream_id: StreamId(0) }
[2024-02-25 05:51:53.623][h2::proto::connection][DEBUG] Connection::poll; connection error error=GoAway(b"", NO_ERROR, Library)
[2024-02-25 05:51:53.628][vaultwarden::sso][ERROR] Request to exchange_refresh_token endpoint failed: ServerResponse(StandardErrorResponse { error: server_error, error_description: Some("Errors.Internal"), error_uri: None })
[2024-02-25 05:51:53.628][vaultwarden::api::identity][ERROR] {"ErrorModel":{"Message":"Request to exchange_refresh_token endpoint failed: ServerResponse(StandardErrorResponse { error: server_error, error_description: Some(\"Errors.Internal\"), error_uri: None })","Object":"error"},"ExceptionMessage":null,"ExceptionStackTrace":null,"InnerExceptionMessage":null,"Message":"Request to exchange_refresh_token endpoint failed: ServerResponse(StandardErrorResponse { error: server_error, error_description: Some(\"Errors.Internal\"), error_uri: None })","Object":"error","ValidationErrors":{"":["Request to exchange_refresh_token endpoint failed: ServerResponse(StandardErrorResponse { error: server_error, error_description: Some(\"Errors.Internal\"), error_uri: None })"]},"error":"","error_description":""}
[2024-02-25 05:51:53.628][response][INFO] (login) POST /identity/connect/token => 401 Unauthorized

[2024-02-25 05:51:53.983][request][INFO] GET /api/config/
[2024-02-25 05:51:53.984][response][INFO] (config) GET /api/config => 200 OK
[2024-02-25 05:51:54.022][request][INFO] GET /api/config/
[2024-02-25 05:51:54.022][response][INFO] (config) GET /api/config => 200 OK
[2024-02-25 05:51:54.460][h2::codec::framed_read][DEBUG] received frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
[2024-02-25 05:51:54.460][h2::codec::framed_read][DEBUG] received frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }
[2024-02-25 05:51:54.460][h2::codec::framed_write][DEBUG] send frame=GoAway { error_code: NO_ERROR, last_stream_id: StreamId(0) }
[2024-02-25 05:51:54.461][h2::proto::connection][DEBUG] Connection::poll; connection error error=GoAway(b"", NO_ERROR, Library)
[2024-02-25 05:51:54.461][vaultwarden::sso][DEBUG] Non jwt refresh_token (expiration set to 1709463114)
[2024-02-25 05:51:54.467][response][INFO] (login) POST /identity/connect/token => 200 OK
[2024-02-25 05:51:54.806][request][INFO] GET /api/config/
[2024-02-25 05:51:54.806][response][INFO] (config) GET /api/config => 200 OK
[2024-02-25 05:51:57.159][vaultwarden::api::core::accounts][DEBUG] Purging auth requests
[2024-02-25 05:51:57.159][vaultwarden::api::core::two_factor][DEBUG] Sending notifications for incomplete 2FA logins
[2024-02-25 05:51:58.442][request][INFO] GET /api/config/
[2024-02-25 05:51:58.442][response][INFO] (config) GET /api/config => 200 OK
[2024-02-25 05:51:58.444][request][INFO] PUT /api/devices/identifier/<uuid>/token
[2024-02-25 05:51:58.449][vaultwarden::api::core::accounts][DEBUG] Device <uuid> is already registered and token is the same
[2024-02-25 05:51:58.449][response][INFO] (put_device_token) PUT /api/devices/identifier/<uuid>/token => 200 OK
[2024-02-25 05:52:37.573][request][INFO] GET /alive
[2024-02-25 05:52:37.573][response][INFO] (alive) GET /alive => 200 OK
[2024-02-25 05:52:47.467][request][INFO] GET /api/sync
[2024-02-25 05:52:47.553][response][INFO] (sync) GET /api/sync?<data..> => 200 OK
[2024-02-25 05:52:48.541][request][INFO] GET /api/config/
[2024-02-25 05:52:48.541][response][INFO] (config) GET /api/config => 200 OK
Halyul commented

Zitadel uses http/2 for communication only, if connection error error=GoAway(b"", NO_ERROR, Library) indicates a failure in communication between vaultwarden and zitadel, then this bug report shall move to dani-garcia/vaultwarden

Timshel commented

Looking at the first log it appears there are 4 calls to the /identity/connect/token :

[2024-02-25 05:51:52.366][request][INFO] POST /identity/connect/token
[2024-02-25 05:51:52.370][request][INFO] POST /identity/connect/token
[2024-02-25 05:51:52.811][request][INFO] POST /identity/connect/token
[2024-02-25 05:51:53.156][request][INFO] POST /identity/connect/token

Both of the later calls will fail since they are done with expired refresh_token (a refresh_token cannot be reused so as soon as a call is done to the endpoint it won't work for another one).

For the others two calls : one appear to have worked :

[2024-02-25 05:51:54.460][h2::codec::framed_write][DEBUG] send frame=GoAway { error_code: NO_ERROR, last_stream_id: StreamId(0) }
[2024-02-25 05:51:54.461][h2::proto::connection][DEBUG] Connection::poll; connection error error=GoAway(b"", NO_ERROR, Library)
[2024-02-25 05:51:54.461][vaultwarden::sso][DEBUG] Non jwt refresh_token (expiration set to 1709463114)
[2024-02-25 05:51:54.467][response][INFO] (login) POST /identity/connect/token => 200 OK

So I'm not very fluent in HTTP/2, but then I would say connection error error=GoAway(b"", NO_ERROR, Library) is not a sign of failure.

If we look at the last response then :

[2024-02-25 05:51:53.623][h2::proto::connection][DEBUG] Connection::poll; connection error error=GoAway(b"", NO_ERROR, Library)
[2024-02-25 05:51:53.628][vaultwarden::sso][ERROR] Request to exchange_refresh_token endpoint failed: ServerResponse(StandardErrorResponse { error: server_error, error_description: Some("Errors.Internal"), error_uri: None })
[2024-02-25 05:51:53.628][vaultwarden::api::identity][ERROR] {"ErrorModel":{"Message":"Request to exchange_refresh_token endpoint failed: ServerResponse(StandardErrorResponse { error: server_error, error_description: Some(\"Errors.Internal\"), error_uri: None })","Object":"error"},"ExceptionMessage":null,"ExceptionStackTrace":null,"InnerExceptionMessage":null,"Message":"Request to exchange_refresh_token endpoint failed: ServerResponse(StandardErrorResponse { error: server_error, error_description: Some(\"Errors.Internal\"), error_uri: None })","Object":"error","ValidationErrors":{"":["Request to exchange_refresh_token endpoint failed: ServerResponse(StandardErrorResponse { error: server_error, error_description: Some(\"Errors.Internal\"), error_uri: None })"]},"error":"","error_description":""}
[2024-02-25 05:51:53.628][response][INFO] (login) POST /identity/connect/token => 401 Unauthorized

It's responding with an Errors.Internal so I'm guessing it triggers an error 500 on Zitadel side, did you check the logs to see if you found anything ?

Halyul commented

I checked Zitadel's logs, all of them are 200 and the error is nowhere to be found. After checking Zitadel's admin console, It looks like a refresh token was issued normally, which is confusing.

Also, I have manually tested using curl, I was unable to reproduce Errors.Internal seen in vaultwarden's logs, which prevents me from further debugging unless I know how vaultwarden communicates with Zitadel internally regarding to this issue :(.

Timshel commented

Hey

Just tested running Zitadel locally with the docker-compose they provide.

I can't reproduce your issue.
Can you describe the flow that fails on mobile ?

To test I set the Access Token Lifetime to 0.1 which mean that after 1 min BitWarden will consider it expired since expiration will be in less than 5min, did not change the other values.

Then I tested the following scenarios in the Android application version 2024.2.0 (9000):

  • Wait for expiration then call synchronize ⇒ ok
  • Lock screen then wait for expiration then unlock ⇒ ok
  • Lock screen / minimize app, wait for expiration then launch and unlock ⇒ ok
  • Lock screen / kill app, wait for expiration then launch and unlock ⇒ ok
  • Kill app, wait for expiration then launch and unlock ⇒ ok

Lowered the session expiration in the application to 1 min then :

  • Wait for expiration then call synchronize ⇒ ok
  • Minimize then wait for expiration then launch and unlock ⇒ ok
  • Kill app, wait for expiration then launch and unlock ⇒ ok
Halyul commented

I have tried 0.1, getting logged out after 6 mins when I reopened the app, because 0.1 hour is 6 mins. Could you try again?

Timshel commented

I pushed the modified docker-compose I used.

It uses a .env (copy the .env.template) file and use the host network for Zitadel to allow to bind an external ip (set ZITADEL_EXTERNALDOMAIN) to be able to test mobile applications. Can you test with it ?

Halyul commented

I'm currently under a strictly restricted network, which prevents me from connecting to lan machines. I will test it out after one or two weeks and let you know.

Timshel commented

In the other issue you mention that

Updated: Refresh token is working correctly in PKCE. The client no longer gets logged out like before.

No idea how that's possible since it should not change the response of the exhange_code ...
Looking back at the Vaultwarden version you are using : oidcwarden/vaultwarden-oidc:latest-alpine, I would not run with latest since it means you are not sure what you are running and when I publish a new version I might introduce breaking change (I try not to but since it's a test version I might).

I'm currently under a strictly restricted network, which prevents me from connecting to lan machines. I will test it out after one or two weeks and let you know.

If you can't change much I would try to explore why do you have so many calls to token endpoint (I never had more than one call when testing all the scenarios on Android) . Cf :

[2024-02-25 05:51:52.366][request][INFO] POST /identity/connect/token
[2024-02-25 05:51:52.370][request][INFO] POST /identity/connect/token
[2024-02-25 05:51:52.811][request][INFO] POST /identity/connect/token
[2024-02-25 05:51:53.156][request][INFO] POST /identity/connect/token

If it's from the same client then it's expected that you will get logout since one of those calls will be made without the correct Vaultwarden refresh_token (the VW refresh_token value is changed with each call and invalidate previous ones).

Halyul commented

Not sure what really happened before. Those 4 requests were sent from the same client as I was testing using only one ios device. But now, I can only see one /identity/connect/token request (w/o PKCE) and the refresh token works as intended while the only change in the system is updating to the latest oidcwarden/vaultwarden-oidc. It is possible that those 4 requests caused the issue, but still unsure about the underlying reason.

Looking back at the Vaultwarden version you are using oidcwarden/vaultwarden-oidc:latest-alpine, I would not run with latest since it means you are not sure what you are running and when I publish a new version I might introduce breaking change

I'm completely agree with you, but ATM I will pull the latest image using oidcwarden/vaultwarden-oidc:latest-alpine before any testing and submitting issues. Thus, I believe I can safely assume that the latest published version is used.

  • 👍1