Skip to content
New issue

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

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

Already on GitHub? # to your account

getting "invalid cipher string format" upon initial login attempt #121

Closed
jpeeler opened this issue Feb 19, 2024 · 19 comments
Closed

getting "invalid cipher string format" upon initial login attempt #121

jpeeler opened this issue Feb 19, 2024 · 19 comments
Assignees
Labels
bug Something isn't working needs testing

Comments

@jpeeler
Copy link

jpeeler commented Feb 19, 2024

I have a hosted vaultwarden instance that I'm using. I've also installed goldwarden via Flatpak.

I executed the custom domain config options as well as goldwarden config set-vault-url. After attempting to login I get this error message:

Login failed: Could not sync vault: could not sync: invalid cipher string format

Is there an assumption being made for the KDF algorithm in use? (Perhaps here?) Wasn't sure if that's what is being described in #24 or not.

On the vaultwarden side I see this:
[2024-02-19 20:48:53.442][vaultwarden::api::identity][INFO] User x@abc.com logged in successfully. IP: 10.0.2.100

@quexten
Copy link
Owner

quexten commented Feb 19, 2024

Thanks for the report.

Is there an assumption being made for the KDF algorithm in use? (Perhaps here?) Wasn't sure if that's what is being described in #24 or not.

The KDF invocation is most likely not the issue here, even when using argon2, a round of pbkdf2 is used to generate the masterpasswordhash to authenticate.

Login failed: Could not sync vault: could not sync: invalid cipher string format

This seems like a corrupted vault entry somewhere, though better logging is required to track this down. I'll add that in a bit.

@quexten quexten added bug Something isn't working needs triage labels Feb 20, 2024
@quexten
Copy link
Owner

quexten commented Feb 21, 2024

Added some debug logging on main, could you try the flatpak from: https://github.com/quexten/goldwarden/actions/runs/7984542101 and post the updated error logs?

@jpeeler
Copy link
Author

jpeeler commented Feb 21, 2024

Launched with GOLDWARDEN_SOCKET_PATH=/home/$USER/.var/app/com.quexten.Goldwarden/data/goldwarden.sock flatpak run --command=goldwarden com.quexten.Goldwarden daemonize &> gold.log. Let me know if you need to privately see the removed dump as well.

[INF] [12:40] [Goldwarden > Keyring] >>> Creating new memguard keyring
[INF] [12:40] [Goldwarden > Agent] >>> Agent listening on /home/jpeeler/.var/app/com.quexten.Goldwarden/data/goldwarden.sock...
Blocking, press ctrl+c to continue...
[INF] [12:40] [Goldwarden > SSH] >>> SSH Agent listening on /home/jpeeler/.var/app/com.quexten.Goldwarden/data/ssh-auth-sock
[WRN] [12:40] [Goldwarden > Agent] >>> Could not monitor idle: The name is not activatable
[INF] [12:40] [Goldwarden > Pinentry] >>> Asking for pin |Unlock Goldwarden|Enter the vault PIN|
[INF] [12:40] [Goldwarden > Pinentry] >>> Got pin from user
[INF] [12:40] [Goldwarden > Auth] >>> Refreshing token
[INF] [12:40] [Goldwarden > Auth] >>> Refreshing using refresh token
[INF] [12:40] [Goldwarden > Auth] >>> Token refreshed
[INF] [12:40] [Goldwarden > Actions] >>> Logging in with master password
[INF] [12:40] [Goldwarden > Pinentry] >>> Asking for pin |Bitwarden Password|Enter your Bitwarden password|
[INF] [12:40] [Goldwarden > Pinentry] >>> Got pin from user
[INF] [12:40] [Goldwarden > Auth] >>> Logged in

I'm removing the dump of what seems to be my actual login data here, even if it is hashed...
{"Ciphers":[{"Attachments":null,"Card":null,"CollectionIds":[],"CreationDate":"2021-08-30T01:02:09.052607Z","Data"...

accept error accept unix /home/jpeeler/.var/app/com.quexten.Goldwarden/data/goldwarden.sock: use of closed network connection
removing sockets and exiting
unlinking /home/jpeeler/.var/app/com.quexten.Goldwarden/data/goldwarden.sock
accept error accept unix /home/jpeeler/.var/app/com.quexten.Goldwarden/data/goldwarden.sock: use of closed network connection
no such file or directory
unlinking
no such file or directory
memguard wiping memory and exiting
accept error accept unix /home/jpeeler/.var/app/com.quexten.Goldwarden/data/goldwarden.sock: use of closed network connection
accept error accept unix /home/jpeeler/.var/app/com.quexten.Goldwarden/data/goldwarden.sock: use of closed network connection
accept error accept unix /home/jpeeler/.var/app/com.quexten.Goldwarden/data/goldwarden.sock: use of closed network connection
accept error accept unix /home/jpeeler/.var/app/com.quexten.Goldwarden/data/goldwarden.sock: use of closed network connection
accept error accept unix /home/jpeeler/.var/app/com.quexten.Goldwarden/data/goldwarden.sock: use of closed network connection
accept error accept unix /home/jpeeler/.var/app/com.quexten.Goldwarden/data/goldwarden.sock: use of closed network connection
accept error accept unix /home/jpeeler/.var/app/com.quexten.Goldwarden/data/goldwarden.sock: use of closed network connection
accept error accept unix /home/jpeeler/.var/app/com.quexten.Goldwarden/data/goldwarden.sock: use of closed network connection
accept error accept unix /home/jpeeler/.var/app/com.quexten.Goldwarden/data/goldwarden.sock: use of closed network connection
accept error accept unix /home/jpeeler/.var/app/com.quexten.Goldwarden/data/goldwarden.sock: use of closed network connection
accept error accept unix /home/jpeeler/.var/app/com.quexten.Goldwarden/data/goldwarden.sock: use of closed network connection
accept error accept unix /home/jpeeler/.var/app/com.quexten.Goldwarden/data/goldwarden.sock: use of closed network connection
accept error accept unix /home/jpeeler/.var/app/com.quexten.Goldwarden/data/goldwarden.sock: use of closed network connection

@quexten
Copy link
Owner

quexten commented Feb 22, 2024

Let me know if you need to privately see the removed dump as well.
I'm removing the dump of what seems to be my actual login data here, even if it is hashed...

Good catch, usually I also write a note to not post credentials or password dumps when asking for logs, seems I missed writing that in this case.

GOLDWARDEN_SOCKET_PATH=/home/$USER/.var/app/com.quexten.Goldwarden/data/goldwarden.sock flatpak run --command=goldwarden com.quexten.Goldwarden daemonize &> gold.log

So usually the flatpak should run the daemon on it's own when you launch it via the desktop entry, or flatpak run (without command). This:

accept error accept unix /home/jpeeler/.var/app/com.quexten.Goldwarden/data/goldwarden.sock: use of closed network connection

Sounds like somehow the daemon is stopped. I'm a bit confused what's exactly happening here. What happens if you completely stop the flatpak:

flatpak kill com.quexten.Goldwarden

and then run it with just:
flatpak run com.quexten.Goldwarden

(it should still show you the agent logs)

@jpeeler
Copy link
Author

jpeeler commented Feb 22, 2024

Is this enough?

❯ flatpak run com.quexten.Goldwarden
starting goldwarden daemon /app/bin/goldwarden
[INF] [15:03] [Goldwarden > Keyring] >>> Creating new memguard keyring
[INF] [15:03] [Goldwarden > Agent] >>> Agent listening on ...
[INF] [15:03] [Goldwarden > SSH] >>> SSH Agent listening on /home/jpeeler/.var/app/com.quexten.Goldwarden/data/ssh-auth-sock
[WRN] [15:03] [Goldwarden > Agent] >>> Could not monitor idle: The name is not activatable
listening for pinentry /app/bin/goldwarden
Enabling autostart...
g-dbus-error-quark: GDBus.Error:org.freedesktop.DBus.Error.UnknownMethod: No such interface “org.freedesktop.portal.Background” on object at path /org/freedesktop/portal/desktop (19)
/app/bin/src/gui/settings.py:84: DeprecationWarning: Gtk.Widget.get_style_context is deprecated
  self.autotype_button.get_style_context().add_class("suggested-action")
/app/bin/src/gui/settings.py:84: DeprecationWarning: Gtk.StyleContext.add_class is deprecated
  self.autotype_button.get_style_context().add_class("suggested-action")
/app/bin/src/gui/settings.py:44: DeprecationWarning: Adw.ActionRow.set_icon_name is deprecated
  row.set_icon_name(icon)
(after clicking quick access)
Traceback (most recent call last):
  File "<frozen runpy>", line 198, in _run_module_as_main
  File "<frozen runpy>", line 88, in _run_code
  File "/app/bin/src/gui/quickaccess.py", line 17, in <module>
    goldwarden.create_authenticated_connection(token)
  File "/app/bin/src/services/goldwarden.py", line 48, in create_authenticated_connection
    raise Exception("Failed to authenticate")
Exception: Failed to authenticate

I can't login or logout using the GUI, so at this point I'm stuck which is why I tried doing things manually previously. Is there a way to execute commands once the daemon is started the normal way?

@quexten
Copy link
Owner

quexten commented Feb 23, 2024

[INF] [15:03] [Goldwarden > Agent] >>> Agent listening on ...

This sounds like another problem, where the agent path was incorrect. Should (hopefully) be fixed in 0.2.13.

Is there a way to execute commands once the daemon is started the normal way?

If you start the daemon the normal way (that is, just starting the flatpak normally), you can run commands with flatpak run, such as:
flatpak run --command=goldwarden com.quexten.Goldwarden vault status

@jpeeler
Copy link
Author

jpeeler commented Feb 23, 2024

I've upgraded my flatpak to 0.2.13. Maybe there's a more thorough purge command, but tried:

rm -rf ~/.var/app/com.quexten.Goldwarden/

Tried logging in once unsuccessfully. I assume I entered the correct password, but even after restarting from the beginning again it still reports bad password.

❯ flatpak run com.quexten.Goldwarden
starting goldwarden daemon /app/bin/goldwarden
[INF] [10:14] [Goldwarden > Keyring] >>> Creating new memguard keyring
[WRN] [10:14] [Goldwarden > Agent] >>> Could not read config: open /home/jpeeler/.var/app/com.quexten.Goldwarden/config/goldwarden.json: no such file or directory
[WRN] [10:14] [Goldwarden > Agent] >>> Config is not locked. SET A PIN!!
[INF] [10:14] [Goldwarden > Agent] >>> Agent listening on /home/jpeeler/.var/app/com.quexten.Goldwarden/data/goldwarden.sock...
[INF] [10:14] [Goldwarden > SSH] >>> SSH Agent listening on /home/jpeeler/.var/app/com.quexten.Goldwarden/data/ssh-auth-sock
[WRN] [10:14] [Goldwarden > Agent] >>> Could not monitor idle: org.freedesktop.DBus.Error.ServiceUnknown
listening for pinentry /app/bin/goldwarden
Enabling autostart...
[INF] [10:14] [Goldwarden > Agent] >>> Received pinentry registration request
[INF] [10:14] [Goldwarden > Agent] >>> Pinentry registration success: true
g-dbus-error-quark: GDBus.Error:org.freedesktop.DBus.Error.UnknownMethod: No such interface “org.freedesktop.portal.Background” on object at path /org/freedesktop/portal/desktop (19)
/app/bin/src/gui/settings.py:84: DeprecationWarning: Gtk.Widget.get_style_context is deprecated
self.autotype_button.get_style_context().add_class("suggested-action")
/app/bin/src/gui/settings.py:84: DeprecationWarning: Gtk.StyleContext.add_class is deprecated
self.autotype_button.get_style_context().add_class("suggested-action")
/app/bin/src/gui/settings.py:44: DeprecationWarning: Adw.ActionRow.set_icon_name is deprecated
row.set_icon_name(icon)
[INF] [10:14] [Goldwarden > Pinentry] >>> Asking for pin |Pin Change|Enter your desired pin|
[INF] [10:14] [Goldwarden > Pinentry] >>> Got pin from user
/app/bin/src/gui/settings.py:253: DeprecationWarning: Gtk.Dialog.get_content_area is deprecated
dialog.get_content_area().append(auth_preference_group)
/app/bin/src/gui/settings.py:270: DeprecationWarning: Gtk.Dialog.add_button is deprecated
dialog.add_button("Login", Gtk.ResponseType.OK)
Gtk-Message: 10:14:51.016: GtkDialog mapped without a transient parent. This is discouraged.
[INF] [10:15] [Goldwarden > Actions] >>> Logging in with master password
[INF] [10:17] [Goldwarden > Actions] >>> Logging in with master password
Traceback (most recent call last):
File "/app/bin/src/gui/settings.py", line 187, in update_labels
logged_in = status["loggedIn"]
~~~~~~^^^^^^^^^^^^
KeyError: 'loggedIn'

--

Also saw this notification once, making me think some traffic is not going to the correct place?

Could not pre-login: Bad Request: {"message":"Traffic from your network looks unusual. Connect to a different network or try again later. [Error Code 6]"}

@quexten
Copy link
Owner

quexten commented Feb 23, 2024

[INF] [10:14] [Goldwarden > Agent] >>> Agent listening on /home/jpeeler/.var/app/com.quexten.Goldwarden/data/goldwarden.sock...

We're slowly getting somewhere, at least this bit is fixed.

Could not pre-login: Bad Request: {"message":"Traffic from your network looks unusual. Connect to a different network or try again later. [Error Code 6]"}

This should only happen on the official servers (bitwarden us and eu). Since you mention you are using vaultwarden, something is wrong here. Did you enter the correct vault url in the login screen again, when logging in?

You can verify this with:
flatpak run --command=goldwarden com.quexten.Goldwarden config get-environment
(DO NOT post the output here, just make sure it's the correct URLs for your vaultwarden server).

To fix, the easiest way would be:
flatpak run --command=goldwarden com.quexten.Goldwarden config set-server "https://vaultwarden.jpeeler.com" (or whatever your vaultwarden url is)

@jpeeler
Copy link
Author

jpeeler commented Feb 23, 2024

Why is the base config not respected from the login dialog? I set the server and verified it via get-environment oon the CLI.

After trying again on the CLI:
❯ flatpak run --command=goldwarden com.quexten.Goldwarden vault login --email jpeeler...
Login failed: Could not sync vault: could not sync: Get "https://vaultwarden.jpeeler.com/api/sync": dial tcp xx.xx.xx.xx:443: connect: connection refused

Gtk-Message: 10:56:01.061: GtkDialog mapped without a transient parent. This is discouraged.
[ERR] [10:56] [Goldwarden > Actions] >>> EnsureIsLoggedIn - chacha20poly1305: ciphertext too short
[INF] [10:56] [Goldwarden > Actions] >>> Logging in with master password

I'm assuming that since I was able to login via the CLI earlier that there's no problem with my vaultwarden setup.

@jpeeler
Copy link
Author

jpeeler commented Feb 23, 2024

I wonder if that port number is correct... My base url is https://:8443

@Roukoswarf
Copy link

Roukoswarf commented Apr 29, 2024

I also get this issue, tested on latest version 0.2.15 built from aur. Got it before on earlier versions, checked back a bit later to see if this ticket would change status, but see that its been idle.

Also vaultwarden, currently 1.30.5, no issues from rbw, or bitwarden official browser plugins or bw-cli.
Anything I could do to help debug?

No custom port, normal 443, not using the flatpak, no connection refused.

goldwarden[85122]: Socket path is empty, overwriting with default path.
goldwarden[85122]: SSH Agent socket path is empty, overwriting with default path.
goldwarden[85122]: [INF] [19:23] [Goldwarden > Keyring] >>> Creating new memguard keyring
goldwarden[85122]: [WRN] [19:23] [Goldwarden > Agent] >>> Could not read config: open /home/alexander/.config/goldwarden/goldwarden.json: no such file or directory
goldwarden[85122]: [WRN] [19:23] [Goldwarden > Agent] >>> Config is not locked. SET A PIN!!
goldwarden[85122]: [INF] [19:23] [Goldwarden > Agent] >>> Agent listening on /home/alexander/.goldwarden.sock...
goldwarden[85122]: Blocking, press ctrl+c to continue...
goldwarden[85122]: [INF] [19:23] [Goldwarden > SSH] >>> SSH Agent listening on /home/alexander/.goldwarden-ssh-agent.sock
goldwarden[85122]: [WRN] [19:23] [Goldwarden > Agent] >>> Could not monitor idle: The name is not activatable
goldwarden[85122]: [ERR] [19:24] [Goldwarden > Actions] >>> EnsureIsLoggedIn - chacha20poly1305: ciphertext too short
goldwarden[85122]: [INF] [19:24] [Goldwarden > Pinentry] >>> Asking for pin |Pin Change|Enter your desired pin|
pinentry-qt[85496]: CapsLockWatcher was compiled without support for unix
pinentry-qt[85496]: Checking for Caps Lock not possible on unsupported platform: "wayland"
goldwarden[85122]: [INF] [19:24] [Goldwarden > Pinentry] >>> Got pin from user
goldwarden[85122]: [INF] [19:26] [Goldwarden > Actions] >>> Logging in with master password
goldwarden[85122]: [INF] [19:26] [Goldwarden > Pinentry] >>> Asking for pin |Bitwarden Password|Enter your Bitwarden password|
pinentry-qt[86142]: CapsLockWatcher was compiled without support for unix
pinentry-qt[86142]: Checking for Caps Lock not possible on unsupported platform: "wayland"
goldwarden[85122]: [INF] [19:26] [Goldwarden > Pinentry] >>> Got pin from user
goldwarden[85122]: [INF] [19:26] [Goldwarden > Pinentry] >>> Asking for pin |Fido2 PIN|Enter your token's PIN|
pinentry-qt[86255]: CapsLockWatcher was compiled without support for unix
pinentry-qt[86255]: Checking for Caps Lock not possible on unsupported platform: "wayland"
goldwarden[85122]: [INF] [19:26] [Goldwarden > Pinentry] >>> Got pin from user
goldwarden[85122]: [ERR] [19:27] [Goldwarden > TwoFactor] >>> Error during FIDO2 two-factor authentication: failed to get assertion: action timed out
goldwarden[85122]: [INF] [19:27] [Goldwarden > Pinentry] >>> Asking for pin |Authenticator Second Factor|Enter your two-factor auth code|
pinentry-qt[86411]: CapsLockWatcher was compiled without support for unix
pinentry-qt[86411]: Checking for Caps Lock not possible on unsupported platform: "wayland"
goldwarden[85122]: [INF] [19:27] [Goldwarden > Pinentry] >>> Got pin from user
goldwarden[85122]: [INF] [19:27] [Goldwarden > Auth] >>> 2FA login successful
goldwarden[85122]: [INF] [19:27] [Goldwarden > Auth] >>> Logged in
goldwarden[85122]: {"Ciphers":[{"Attachments":null,"Card":null,"CollectionIds":[],"CreationDate":"2023-04-10T22:49:35.483655Z","Data":{.......

Alongside the error on the CLI:

Login failed: Could not sync vault: could not sync: invalid cipher string format, missing parts, length: 49type: 0

@quexten quexten self-assigned this Apr 29, 2024
@quexten
Copy link
Owner

quexten commented Apr 29, 2024

@Roukoswarf could you post the output of:
goldwarden vault status
then try:
goldwarden vault purge
goldwarden vault pin set
and then configure the server & log in.

@Roukoswarf
Copy link

alex@home ~ % goldwarden vault status
{"lastSynced":"1970-01-01 00:00:00 +0000 UTC","locked":true,"loggedIn":false,"loginEntries":0,"noteEntries":0,"pinSet":true,"websocketConnected":false}
alex@home ~ % goldwarden vault purge
Purged
alex@home ~ % goldwarden vault pin set
Pin updated
alex@home ~ % goldwarden config set-server https://vault.rouk.org
Done
alex@home ~ % goldwarden vault login --email alex@rouk.org       
Login failed: Could not sync vault: could not sync: invalid cipher string format, missing parts, length: 49type: 0

I could try making a new account in case its an artifact of an old vault? The vault is using argon2id with the currently recommended settings by upstream. 3 KDF iterations, 64MB memory, 4 KDF parallelism.

I tried logging in with api keys, no change, i see my vault contents of some sort in the log, where i cut it in the last line of the log given before, login does appear to succeed, the failure is after.

It asks for my fido2 in the logs, and on screen, but always hangs for a while then fails and asks for OTP and succeeds, but thats probably a different issue, not sure why fido2 is failing, works via browser/other clients as well.

@quexten
Copy link
Owner

quexten commented Apr 29, 2024

Login failed: Could not sync vault: could not sync: invalid cipher string format, missing parts, length: 49type: 0

Oh this is interesting. You seem to have a cipher of type '0', that is AesCbc256_B64 without mac. I really thought this was already force migrated by the official clients some time ago. I wonder if it actually has this type, or if it's just the default because parsing is failing somewhere..

@Roukoswarf
Copy link

How would I migrate this manually? I use the official client which doesn't complain about anything, or convert it either I guess. I recently (6 months ago) change from pkbdf to argon, which id have expected to re-key everything, would a fresh master password force a whole recalc?

Cant be vaultwarden specific, server doesn't do the crypt.

@quexten
Copy link
Owner

quexten commented Apr 29, 2024

In the web vault:
image
Be sure to have the marked setting checked.
(just keep the same master password as current and new).

As a disclaimer, it's probably best to export a copy of your vault before doing this, because in some very rare cases, key rotation can cause the vault contents to get corrupted (f.e if the local state is broken and you then rotate)

Changing kdf does not rotate the encryption keys, but only re-encrypts the usersymmetric key with the kdf-derived master key.

@Roukoswarf
Copy link

Roukoswarf commented Apr 29, 2024

Rotating encryption keys doesnt seem to actually work, apps get logged out, but the browser console log is full of "mac required" errors. I'm willing to blame vaultwarden-web for this, but google digs up nothing on a workaround.

A fresh account logs in successfully via goldwarden, and successfully rotates account encryption.

Can safely say that this is not a goldwarden issue, though some messaging would be good to add, not sure of a better workaround than recreation, clients behave fine, but you cannot rotate encryption key.

Wonder if purge would reset encryption, or if it just deletes everything without rotation.

Edit: export -> purge -> import does resolve the issue without a new vault entirely.

@quexten
Copy link
Owner

quexten commented Apr 29, 2024

Rotating encryption keys doesnt seem to actually work, apps get logged out, but the browser console log is full of "mac required" errors. I'm willing to blame vaultwarden-web for this, but google digs up nothing on a workaround.

Very weird. Might actually be a bug in vaultwarden where it kept old ciphers around despite rotation.

Can safely say that this is not a goldwarden issue, though some messaging would be good to add, not sure of a better workaround than recreation, clients behave fine, but you cannot rotate encryption key.

In the latest release, the offending ciphers should get ignored, and the rest will get synced, with warnings printed to console.

@jpeeler
Copy link
Author

jpeeler commented May 3, 2024

FWIW, I was able to get everything working now. I assume some changes were made in the latest release. Will leave it up to either of you as to whether or not this should be closed now.

One small oddity I encountered was when setting the AUTH_SSH_SOCK using a tilda gave me:
❯ ssh-add -L
Error connecting to agent: No such file or directory

Using the full expanded path works fine though.

# for free to join this conversation on GitHub. Already have an account? # to comment
Labels
bug Something isn't working needs testing
Projects
None yet
Development

No branches or pull requests

3 participants