Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
ChoosenMEME opened this issue Jun 23, 2024 · 2 comments
Open

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

ChoosenMEME opened this issue Jun 23, 2024 · 2 comments

Comments

@ChoosenMEME
Copy link

ChoosenMEME commented Jun 23, 2024

Subject of the issue

Creation, edits and delete of entries slow

Deployment environment

Your environment (Generated via diagnostics page)

  • Vaultwarden version: v1.30.5
  • Web-vault version: v2024.1.2b
  • 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: SQLite
  • Database version: 3.44.0
  • Clients used:
  • Reverse proxy and version:
  • Other relevant information:

Config (Generated via diagnostics page)

Show Running Config

Environment settings which are overridden:

{
  "_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
}
  • vaultwarden version: 1.30.5
  • Install method: Docker Image with docker compose

  • Clients used:
    web vault, desktop, Android

  • Reverse proxy and version:
    traefik 3.0.3 (for local network)
    Cloudflare Tunnel (for external network)

  • Other relevant details:

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 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
Copy link
Author

ChoosenMEME commented Jun 23, 2024

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
Copy link
Contributor

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 #3988 resolves the issue

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants