dani-garcia / vaultwarden

Unofficial Bitwarden compatible server written in Rust, formerly known as bitwarden_rs
GNU Affero General Public License v3.0
34.71k stars 1.69k forks source link

Creation, edits and delete of entries slow 5+ seconds each #4669

Open ChoosenMEME opened 1 week ago

ChoosenMEME commented 1 week ago

Subject of the issue

Creation, edits and delete of entries slow

Deployment environment

Your environment (Generated via diagnostics page)

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": true, "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": null, "experimental_client_feature_flags": "fido2-vault-credentials", "extended_logging": true, "helo_name": null, "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": 120, "invitation_org_name": "Vaultwarden", "invitations_allowed": true, "ip_header": "X-Real-IP", "job_poll_interval_ms": 30000, "log_file": null, "log_level": "Info", "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": false, "org_groups_enabled": false, "password_hints_allowed": true, "password_iterations": 600000, "push_enabled": true, "push_identity_uri": "https://identity.bitwarden.eu", "push_installation_id": "***", "push_installation_key": "***", "push_relay_uri": "https://api.bitwarden.eu", "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": false, "signups_verify_resend_limit": 6, "signups_verify_resend_time": 3600, "smtp_accept_invalid_certs": true, "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": "Vaultwarden", "smtp_host": "*****************", "smtp_password": "***", "smtp_port": 25, "smtp_security": "starttls", "smtp_ssl": null, "smtp_timeout": 15, "smtp_username": "************************", "templates_folder": "data/templates", "tmp_folder": "data/tmp", "trash_auto_delete_days": null, "trash_purge_schedule": "0 5 0 * * *", "use_sendmail": false, "use_syslog": false, "user_attachment_limit": null, "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": "79913", "yubico_secret_key": "***", "yubico_server": null } ```

The vault itself is not that big 1 User and ~500 Entries import/export not really an option due to passkeys not being transfered that way

Steps to reproduce

1. Stopped the old container 2. Copied whole /data directory from old to new host to (following [backup guide](https://github.com/dani-garcia/vaultwarden/wiki/Backing-up-your-vault) and only copying relevant non empty files/folders also did not help) 3. started the new container (here also looong wait time) 4. login and edit/create or delete entries 5. wait aprox. 5 seconds for each of those actions to complete ### Expected behaviour

Faster editing, creation or deletion of entries. Expected behaviour occurs if the /data directory is empty and everything is created from scratch with identical configuration otherwise. Expected behaviour also still occurs on old System where the ?data directory is originally from.

Actual behaviour

Each editing, creation or deletion aprox. 5 seconds for each of those actions to complete.

Troubleshooting data

ChoosenMEME commented 1 week ago

Edit: testing to minimize the environment revealed that my problem is caused by Push Notifications as removing the following from docker compose seems to have resolved my complaint.

  PUSH_ENABLED: true 
  PUSH_INSTALLATION_ID: ${PUSH_INSTALLATION_ID}
  PUSH_INSTALLATION_KEY: ${PUSH_INSTALLATION_KEY}
  PUSH_RELAY_URI: https://api.bitwarden.eu
  PUSH_IDENTITY_URI: https://identity.bitwarden.eu

Same with US servers

maybe debug logs are helpful

Show Logs ``` [2024-06-24 01:26:02.436][reqwest::connect][DEBUG] starting new connection: https://identity.bitwarden.eu/ [2024-06-24 01:26:02.437][trust_dns_proto::xfer::dns_handle][DEBUG] querying: identity.bitwarden.eu A [2024-06-24 01:26:02.437][trust_dns_resolver::name_server::name_server_pool][DEBUG] sending request: [Query { name: Name("identity.bitwarden.eu"), query_type: A, query_class: IN }] [2024-06-24 01:26:02.437][trust_dns_resolver::name_server::name_server][DEBUG] reconnecting: NameServerConfig { socket_addr: 127.0.0.11:53, protocol: Udp, tls_dns_name: None, trust_negative_responses: false, bind_addr: None } [2024-06-24 01:26:02.437][trust_dns_proto::xfer][DEBUG] enqueueing message:QUERY:[Query { name: Name("identity.bitwarden.eu"), query_type: A, query_class: IN }] [2024-06-24 01:26:02.437][trust_dns_proto::udp::udp_client_stream][DEBUG] final message: ; header 24063:QUERY:RD:NoError:QUERY:0/0/0 ; query ;; identity.bitwarden.eu. IN A [2024-06-24 01:26:02.437][trust_dns_proto::udp::udp_stream][DEBUG] created socket successfully [2024-06-24 01:26:06.558][trust_dns_proto::udp::udp_client_stream][DEBUG] received message id: 24063 [2024-06-24 01:26:06.559][trust_dns_resolver::error][DEBUG] Response:; header 24063:RESPONSE:RD,TC,RA:NoError:QUERY:0/0/0 ; query ;; identity.bitwarden.eu. IN A ; answers 0 ; nameservers 0 ; additionals 0 [2024-06-24 01:26:06.559][trust_dns_resolver::name_server::name_server_pool][DEBUG] truncated response received, retrying over TCP [2024-06-24 01:26:06.559][trust_dns_resolver::name_server::name_server][DEBUG] reconnecting: NameServerConfig { socket_addr: 127.0.0.11:53, protocol: Tcp, tls_dns_name: None, trust_negative_responses: false, bind_addr: None } [2024-06-24 01:26:06.559][trust_dns_proto::tcp::tcp_stream][DEBUG] TCP connection established to: 127.0.0.11:53 [2024-06-24 01:26:06.559][trust_dns_proto::xfer][DEBUG] enqueueing message:QUERY:[Query { name: Name("identity.bitwarden.eu"), query_type: A, query_class: IN }] [2024-06-24 01:26:06.559][trust_dns_proto::xfer::dns_multiplexer][DEBUG] sending message id=50803 [2024-06-24 01:26:06.559][trust_dns_proto::xfer::dns_multiplexer][DEBUG] final message: ; header 50803:QUERY:RD:NoError:QUERY:0/0/0 ; query ;; identity.bitwarden.eu. IN A [2024-06-24 01:26:06.559][trust_dns_proto::tcp::tcp_stream][DEBUG] sending message len: 39 to: 127.0.0.11:53 [2024-06-24 01:26:06.563][trust_dns_proto::tcp::tcp_stream][DEBUG] in ReadTcpState::LenBytes: 0 [2024-06-24 01:26:06.563][trust_dns_proto::tcp::tcp_stream][DEBUG] got length: 92 [2024-06-24 01:26:06.563][trust_dns_proto::tcp::tcp_stream][DEBUG] move ReadTcpState::Bytes: 92 [2024-06-24 01:26:06.563][trust_dns_proto::tcp::tcp_stream][DEBUG] in ReadTcpState::Bytes: 92 [2024-06-24 01:26:06.563][trust_dns_proto::tcp::tcp_stream][DEBUG] reset ReadTcpState::LenBytes: 0 [2024-06-24 01:26:06.563][trust_dns_proto::tcp::tcp_stream][DEBUG] returning bytes [2024-06-24 01:26:06.563][trust_dns_proto::tcp::tcp_stream][DEBUG] returning buffer [2024-06-24 01:26:06.563][trust_dns_resolver::error][DEBUG] Response:; header 50803:RESPONSE:RD,RA:NoError:QUERY:2/0/0 ; query ;; identity.bitwarden.eu. IN A ; answers 2 identity.bitwarden.eu. 296 IN CNAME n.sni.global.fastly.net. n.sni.global.fastly.net. 56 IN A 146.75.117.91 ; nameservers 0 ; additionals 0 [2024-06-24 01:26:06.563][trust_dns_resolver::error][DEBUG] Response:; header 50803:RESPONSE:RD,RA:NoError:QUERY:2/0/0 ; query ;; identity.bitwarden.eu. IN A ; answers 2 identity.bitwarden.eu. 296 IN CNAME n.sni.global.fastly.net. n.sni.global.fastly.net. 56 IN A 146.75.117.91 ; nameservers 0 ; additionals 0 [2024-06-24 01:26:06.601][h2::client][DEBUG] binding client connection [2024-06-24 01:26:06.601][h2::client][DEBUG] client connection bound [2024-06-24 01:26:06.601][h2::codec::framed_write][DEBUG] send frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 } [2024-06-24 01:26:06.601][h2::proto::connection][DEBUG] Connection; peer=Client [2024-06-24 01:26:06.602][h2::codec::framed_write][DEBUG] send frame=WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 } [2024-06-24 01:26:06.602][h2::codec::framed_write][DEBUG] send frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) } [2024-06-24 01:26:06.602][h2::codec::framed_write][DEBUG] send frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) } [2024-06-24 01:26:06.616][h2::codec::framed_read][DEBUG] received frame=Settings { flags: (0x0), max_concurrent_streams: 100 } [2024-06-24 01:26:06.616][h2::codec::framed_write][DEBUG] send frame=Settings { flags: (0x1: ACK) } [2024-06-24 01:26:06.616][h2::codec::framed_read][DEBUG] received frame=WindowUpdate { stream_id: StreamId(0), size_increment: 16711681 } [2024-06-24 01:26:06.616][h2::codec::framed_read][DEBUG] received frame=Settings { flags: (0x1: ACK) } [2024-06-24 01:26:06.617][h2::proto::settings][DEBUG] received settings ACK; applying Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 } [2024-06-24 01:26:06.681][h2::codec::framed_read][DEBUG] received frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) } [2024-06-24 01:26:06.681][h2::codec::framed_read][DEBUG] received frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) } [2024-06-24 01:26:06.682][vaultwarden::api::push][DEBUG] Token still valid for 43199 [2024-06-24 01:26:06.682][trust_dns_proto::xfer][DEBUG] ignoring send error on disconnected stream [2024-06-24 01:26:06.682][trust_dns_proto::xfer::dns_multiplexer][DEBUG] stream is done: TCP(127.0.0.11:53) [2024-06-24 01:26:06.682][trust_dns_proto::xfer::dns_exchange][DEBUG] io_stream is done, shutting down [2024-06-24 01:26:06.682][trust_dns_proto::xfer::dns_exchange][DEBUG] io_stream is done, shutting down [2024-06-24 01:26:06.699][reqwest::connect][DEBUG] starting new connection: https://api.bitwarden.eu/ [2024-06-24 01:26:06.699][trust_dns_proto::xfer::dns_handle][DEBUG] querying: api.bitwarden.eu A [2024-06-24 01:26:06.699][trust_dns_resolver::name_server::name_server_pool][DEBUG] sending request: [Query { name: Name("api.bitwarden.eu"), query_type: A, query_class: IN }] [2024-06-24 01:26:06.699][trust_dns_resolver::name_server::name_server][DEBUG] reconnecting: NameServerConfig { socket_addr: 127.0.0.11:53, protocol: Udp, tls_dns_name: None, trust_negative_responses: false, bind_addr: None } [2024-06-24 01:26:06.699][trust_dns_proto::xfer][DEBUG] enqueueing message:QUERY:[Query { name: Name("api.bitwarden.eu"), query_type: A, query_class: IN }] [2024-06-24 01:26:06.699][trust_dns_proto::udp::udp_client_stream][DEBUG] final message: ; header 16779:QUERY:RD:NoError:QUERY:0/0/0 ; query ;; api.bitwarden.eu. IN A [2024-06-24 01:26:06.699][h2::codec::framed_write][DEBUG] send frame=GoAway { error_code: NO_ERROR, last_stream_id: StreamId(0) } [2024-06-24 01:26:06.699][h2::proto::connection][DEBUG] Connection::poll; connection error error=GoAway(b"", NO_ERROR, Library) [2024-06-24 01:26:06.699][trust_dns_proto::udp::udp_stream][DEBUG] created socket successfully [2024-06-24 01:26:10.740][trust_dns_proto::udp::udp_client_stream][DEBUG] received message id: 16779 [2024-06-24 01:26:10.740][trust_dns_resolver::error][DEBUG] Response:; header 16779:RESPONSE:RD,TC,RA:NoError:QUERY:0/0/0 ; query ;; api.bitwarden.eu. IN A ; answers 0 ; nameservers 0 ; additionals 0 [2024-06-24 01:26:10.740][trust_dns_resolver::name_server::name_server_pool][DEBUG] truncated response received, retrying over TCP [2024-06-24 01:26:10.740][trust_dns_resolver::name_server::name_server][DEBUG] reconnecting: NameServerConfig { socket_addr: 127.0.0.11:53, protocol: Tcp, tls_dns_name: None, trust_negative_responses: false, bind_addr: None } [2024-06-24 01:26:10.740][trust_dns_proto::tcp::tcp_stream][DEBUG] TCP connection established to: 127.0.0.11:53 [2024-06-24 01:26:10.740][trust_dns_proto::xfer][DEBUG] enqueueing message:QUERY:[Query { name: Name("api.bitwarden.eu"), query_type: A, query_class: IN }] [2024-06-24 01:26:10.740][trust_dns_proto::xfer::dns_multiplexer][DEBUG] sending message id=58009 [2024-06-24 01:26:10.740][trust_dns_proto::xfer::dns_multiplexer][DEBUG] final message: ; header 58009:QUERY:RD:NoError:QUERY:0/0/0 ; query ;; api.bitwarden.eu. IN A [2024-06-24 01:26:10.740][trust_dns_proto::tcp::tcp_stream][DEBUG] sending message len: 34 to: 127.0.0.11:53 [2024-06-24 01:26:10.745][trust_dns_proto::tcp::tcp_stream][DEBUG] in ReadTcpState::LenBytes: 0 [2024-06-24 01:26:10.745][trust_dns_proto::tcp::tcp_stream][DEBUG] got length: 87 [2024-06-24 01:26:10.745][trust_dns_proto::tcp::tcp_stream][DEBUG] move ReadTcpState::Bytes: 87 [2024-06-24 01:26:10.745][trust_dns_proto::tcp::tcp_stream][DEBUG] in ReadTcpState::Bytes: 87 [2024-06-24 01:26:10.745][trust_dns_proto::tcp::tcp_stream][DEBUG] reset ReadTcpState::LenBytes: 0 [2024-06-24 01:26:10.745][trust_dns_proto::tcp::tcp_stream][DEBUG] returning bytes [2024-06-24 01:26:10.745][trust_dns_proto::tcp::tcp_stream][DEBUG] returning buffer [2024-06-24 01:26:10.745][trust_dns_resolver::error][DEBUG] Response:; header 58009:RESPONSE:RD,RA:NoError:QUERY:2/0/0 ; query ;; api.bitwarden.eu. IN A ; answers 2 api.bitwarden.eu. 296 IN CNAME n.sni.global.fastly.net. n.sni.global.fastly.net. 52 IN A 146.75.117.91 ; nameservers 0 ; additionals 0 [2024-06-24 01:26:10.745][trust_dns_resolver::error][DEBUG] Response:; header 58009:RESPONSE:RD,RA:NoError:QUERY:2/0/0 ; query ;; api.bitwarden.eu. IN A ; answers 2 api.bitwarden.eu. 296 IN CNAME n.sni.global.fastly.net. n.sni.global.fastly.net. 52 IN A 146.75.117.91 ; nameservers 0 ; additionals 0 ```
stefan0xC commented 1 week ago

maybe debug logs are helpful

They point to DNS resolution as the cause of the issue as each lookup takes about 4 seconds:

[2024-06-24 01:26:02.437][trust_dns_proto::udp::udp_stream][DEBUG] created socket successfully
[2024-06-24 01:26:06.558][trust_dns_proto::udp::udp_client_stream][DEBUG] received message id: 24063
[2024-06-24 01:26:06.699][trust_dns_proto::udp::udp_stream][DEBUG] created socket successfully
[2024-06-24 01:26:10.740][trust_dns_proto::udp::udp_client_stream][DEBUG] received message id: 16779

So you might want to test it with a different DNS name server? Or try the testing image if https://github.com/dani-garcia/vaultwarden/pull/3988 resolves the issue