621846 - "Couldn't decrypt string" while syncing login changes

Status: RESOLVED FIXED

(Toolkit :: Password Manager, defect, P1)

Description

[Henrik Gemal]

I'm unable to syn due to:

Error: [Exception... "Couldn't decrypt string"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: jar:file:///C:/Program%20Files/Mozilla/nightly/Mozilla%20Firefox/omni.jar!/components/crypto-SDR.js :: <TOP_LEVEL> :: line 205"  data: no]
Source File: jar:file:///C:/Program%20Files/Mozilla/nightly/Mozilla%20Firefox/omni.jar!/components/crypto-SDR.js
Line: 205

I've restarted in safemode with all addons disabled and is stil unable to sync due to the above error

using latest nightly build

Comment 1

[Henrik Gemal]

I also see:

Error: [Exception... "'specified GUID already exists' when calling method: [nsILoginManagerStorage::addLogin]"  nsresult: "0x8057001e (NS_ERROR_XPC_JS_THREW_STRING)"  location: "JS frame :: jar:file:///C:/Program%20Files/Mozilla/nightly/Mozilla%20Firefox/omni.jar!/components/nsLoginManager.js :: <TOP_LEVEL> :: line 411"  data: no]
Source File: jar:file:///C:/Program%20Files/Mozilla/nightly/Mozilla%20Firefox/omni.jar!/components/nsLoginManager.js
Line: 411

Error: [Exception... "'Error: NS_ERROR_XPC_JS_THREW_STRING' when calling method: [nsIStreamListener::onStopRequest]"  nsresult: "0x8057001c (NS_ERROR_XPC_JS_THREW_JS_OBJECT)"  location: "<unknown>"  data: no]

Comment 2

[Philipp von Weitershausen [:philikon]]

(In reply to comment #0)
> I'm unable to syn due to:
> 
> Error: [Exception... "Couldn't decrypt string"  nsresult: "0x80004005
> (NS_ERROR_FAILURE)"  location: "JS frame ::
> jar:file:///C:/Program%20Files/Mozilla/nightly/Mozilla%20Firefox/omni.jar!/components/crypto-SDR.js
> :: <TOP_LEVEL> :: line 205"  data: no]
> Source File:
> jar:file:///C:/Program%20Files/Mozilla/nightly/Mozilla%20Firefox/omni.jar!/components/crypto-SDR.js
> Line: 205

crypto-SDR.js is not a Sync file, it's a password manager thing: https://mxr.mozilla.org/mozilla-central/source/toolkit/components/passwordmgr/src/crypto-SDR.js

(In reply to comment #1)
> I also see:
> 
> Error: [Exception... "'specified GUID already exists' when calling method:
> [nsILoginManagerStorage::addLogin]"  nsresult: "0x8057001e
> (NS_ERROR_XPC_JS_THREW_STRING)"  location: "JS frame ::
> jar:file:///C:/Program%20Files/Mozilla/nightly/Mozilla%20Firefox/omni.jar!/components/nsLoginManager.js
> :: <TOP_LEVEL> :: line 411"  data: no]
> Source File:
> jar:file:///C:/Program%20Files/Mozilla/nightly/Mozilla%20Firefox/omni.jar!/components/nsLoginManager.js
> Line: 411
> 
> Error: [Exception... "'Error: NS_ERROR_XPC_JS_THREW_STRING' when calling
> method: [nsIStreamListener::onStopRequest]"  nsresult: "0x8057001c
> (NS_ERROR_XPC_JS_THREW_JS_OBJECT)"  location: "<unknown>"  data: no]

That may or may not be unrelated. If you fix the above issue and this issue persists, please file a new bug.

Comment 3

[Justin Dolske [:Dolske]]

Err, I assume this is this running on profiles with Sync enabled?

Regarding comment 0...

That error gets logged when we can't decrypt a stored (encrypted) login. Have you recently moved files between profiles? I think sync doesn't twiddle the encrypted passwords directly, so this seems unlikely to be caused by Sync.

Regarding comment 1...

Password manager does not allow adding/modifying a login such that you would end up with 2 logins with the same GUID. It explicitly checks this when the APIs are called.

But the part of password manager which interacts with webpages never explicitly sets a GUID on new logins, which causes a random GUID to be generated. So this implies to me that Sync or some addon is trying to add a login which already has a GUID set.


Offhand, I'd guess that whatever happened to result in an undecryptable login is causing 2. The APIs don't return undecryptable logins, but the GUID checks don't care if the login can be decrypted or not.

Comment 4

[Philipp von Weitershausen [:philikon]]

Henrik, please turn on Sync's log (set services.sync.log.appender.debugLog.enabled to true) and trace logging for password sync (set services.sync.log.logger.engine.passwords to Trace). Then please restart and sync again.

about:sync-log should now have a lot more information that may help us track down what Sync is trying to do. It would be good if you could attach this log to the bug, but please be careful since it will also contain your passwords in cleartext. So please make sure you get rid of that data in the logs. Thanks!

Comment 5

[Henrik Gemal]

Attachment: Sync log

I'm still unable to sync

Comment 6

[Henrik Gemal]

Anything I can do to get some more information to help fix this bug which is still beating me.

The latest sync log seems to say:
'specified GUID already exists'

I'm still unable to sync due to this bug :(

-------------------------
2011-01-12 22:56:17	Engine.Passwords     TRACE	Incoming: { id: {0010061d-28cb-407b-aab3-0d8221d6a59e}
  index: 0
  modified: 1292324751.03
  payload: {"id":"{0010061d-28cb-407b-aab3-0d8221d6a59e}","hostname":"https://aktiebog2.prod.bec.dk","formSubmitURL":"https://aktiebog2.prod.bec.dk","httpRealm":null,"username":"696961511","password":"xxxxx","usernameField":"VPKontonummer","passwordField":"kode"}
  collection: passwords }
2011-01-12 22:56:17	Engine.Passwords     TRACE	Reconcile step 1: Check for conflicts
2011-01-12 22:56:17	Engine.Passwords     TRACE	Reconcile step 2: Check for updates
2011-01-12 22:56:17	Store.Passwords      TRACE	No items matching {0010061d-28cb-407b-aab3-0d8221d6a59e} found. Ignoring
2011-01-12 22:56:17	Engine.Passwords     TRACE	Reconcile step 2.5: Don't dupe deletes
2011-01-12 22:56:17	Engine.Passwords     TRACE	Reconcile step 3: Find dupes
2011-01-12 22:56:17	Store.Passwords      TRACE	No items matching {0010061d-28cb-407b-aab3-0d8221d6a59e} found. Ignoring
2011-01-12 22:56:17	Store.Passwords      DEBUG	Adding login for https://aktiebog2.prod.bec.dk
2011-01-12 22:56:17	Collection           WARN	Got exception calling onProgress handler during fetch of https://phx-sync121.services.mozilla.com/1.0/gemal/storage/passwords?full=1
2011-01-12 22:56:17	Collection           DEBUG	'specified GUID already exists' when calling method: [nsILoginManagerStorage::addLogin] Stack trace: resource://gre/components/nsLoginManager.js:411 < PasswordStore__create()@resource://services-sync/engines/passwords.js:192 < Store_applyIncoming()@resource://services-sync/stores.js:66 < resource://services-sync/engines.js:486 < innerBind()@resource://services-sync/util.js:1398 < resource://services-sync/base_records/collection.js:154 < Channel_onDataAvail()@resource://services-sync/resource.js:464
2011-01-12 22:56:17	Engine.Passwords     TRACE	Event: weave:engine:sync:error
2011-01-12 22:56:17	Engine.Passwords     DEBUG	Total (ms): sync 3622, processIncoming 853, syncStartup 2769, findDupe 6, reconcile 10, syncCleanup 0
2011-01-12 22:56:17	Service.Main         DEBUG	passwords failed: NS_ERROR_XPC_JS_THREW_STRING JS Stack trace: Res_get()@resource.js:376 < SyncEngine__processIncoming()@engines.js:511 < ()@engines.js:203 < SyncEngine__sync()@engines.js:768 < ()@engines.js:203 < WrappedNotify()@util.js:158 < Engine_sync()@engines.js:213 < WeaveSvc__syncEngine([object Object])@service.js:1868 < ()@service.js:1754 < WrappedNotify()@util.js:158 < WrappedLock()@util.js:126 < _lockedSync()@service.js:1659 < ()@service.js:1650 < WrappedCatch()@util.js:100 < sync(false)@service.js:1631 < ([object Object])@service.js:571 < notify([object XPCWrappedNative_NoHelper])@util.js:1137
2011-01-12 22:56:17	Engine.Prefs         INFO	0 outgoing items pre-reconciliation
2011-01-12 22:56:17	Engine.Prefs         INFO	Records: 0 applied, 0 reconciled.

Comment 9

[V@no]

On top of unable to sync, my Firefox become unusable while it trying to sync. It freezes for 2 seconds every other second until it stops syncing, which usually takes a few minutes.

Comment 11

[Mark Hammond [:markh] [:mhammond]]

Attachment: addlogin-failure-with-guid.patch

I believe the problem here is that for whatever reason, the existing passwords are unable to be decrypted. test_logins_decrypt_failure.js explicitly tests that after a master-password reset, logins can be re-added for the existing entries which are now unable to be decrypted - however, it fails to handle the case when a GUID is specified. When Sync sees an incoming record, it attempts to find an existing one (which it correctly can't as it can't be decrypted), so calls addLogin specifying the GUID stored on the server - which then fails.

The end result of this is that once we are in this state, sync will forever fail to repopulate logins from the server.

I'm attaching a test change which demonstrates this failure. With this patch, test_logins_decrypt_failure.js fails with:

> 0:00.76 LOG: Thread-1 ERROR Unexpected exception NS_ERROR_XPC_JAVASCRIPT_ERROR_WITH_DETAILS: [JavaScript Error: "specified GUID already exists" {file: "file:///o:/src/moz/gecko/obj-release/dist/bin/components/storage-json.js" line: 119}]'[JavaScript Error: "specified GUID already exists" ...


The simplest way to otherwise reproduce is to delete key3.db from your profile and arrange to sync all passwords - each one will fail with this error.

Matt, do you have any ideas/suggestions here?

Comment 13

[Mark Hammond [:markh] [:mhammond]]

I think a way forward here is reasonably clear - if "get" returns null due to an existing record being unable to be decrypted, "add" should allow that existing entry to be overridden.

Comment 14

[Mark Hammond [:markh] [:mhammond]]

Attachment: Bug 621846 - allow an unencryptable login with a GUID to be replaced by an item with the same GUID.

Review commit: https://reviewboard.mozilla.org/r/154798/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/154798/

Comment 15

[Mark Hammond [:markh] [:mhammond]]

Matt, I know you are snowed under with reviews, but a quick look at the log for storage-json.js didn't offer obvious alternatives - but obviously feel free to delegate this.

Comment 16

[Matthew N. [:MattN]]

Comment on attachment 8883850 [details]
Bug 621846 - allow an unencryptable login with a GUID to be replaced by an item with the same GUID.

https://reviewboard.mozilla.org/r/154798/#review163102

::: toolkit/components/passwordmgr/storage-json.js:126
(Diff revision 1)
> +        let existing = this._searchLogins({guid})[0];
> +        if (this._decryptLogins(existing).length) {
> +          // Existing item is good, so it's an error to try and re-add it.
> -        throw new Error("specified GUID already exists");
> +          throw new Error("specified GUID already exists");
> +        }
> +        // find the remove the existing bad entry.

s/find the/find and/

::: toolkit/components/passwordmgr/storage-json.js:166
(Diff revision 1)
>      // Send a notification that a login was added.
>      LoginHelper.notifyStorageChanged("addLogin", loginClone);

Wouldn't it cause less problems to go down the modifyLogin path in this case? I can imagine consumers of the observer notification getting confused be an "addition" of a login that already existed.

I haven't look into the feasibility but perhaps instead of doing the .splice (which is a bit risky if the addition later fails), can we instead forward the call to `modifyLogin` at that point?

Re-flag for review if you disagree.

Comment 17

[Mark Hammond [:markh] [:mhammond]]

(In reply to Matthew N. [:MattN] (huge backlog; PM if requests are blocking you) from comment #16)

> Wouldn't it cause less problems to go down the modifyLogin path in this
> case? I can imagine consumers of the observer notification getting confused
> be an "addition" of a login that already existed.

Note that this is already true today for items without a GUID - the item does already exist, it just can't be decrypted, so findLogins etc don't return it and re-adding the "same" login succeeds and sends an addLogin notification.

IOW, it seems wrong that the observer behaviour would be different depending on whether the item happened to have a GUID or not.

> I haven't look into the feasibility but perhaps instead of doing the .splice
> (which is a bit risky if the addition later fails), can we instead forward
> the call to `modifyLogin` at that point?

The problem with this is that we don't have an "oldLogin" to pass as it can't be decrypted (which also applies to sending a modifyLogin notification - we can't send the old login as the existing one can't be decrypted.)

I'm happy to take that approach if you still think it would be better, but it would probably involve refactoring modifyLogin significantly - eg, we'd need to avoid the calls to _getIdForLogin() and findLogins() as both will fail here as the old login can't be decrypted.

Or am I mis-understanding what you suggest?

Comment 18

[Bill]

I really need help on this. Firefox will not sync my passwords to the computer I am on right now. If I put passwords in manually it will only keep them until I turn the computer off.  This is really causing problems and I need help, PLEASE

Comment 19

[Mark Hammond [:markh] [:mhammond]]

(In reply to Bill from comment #18)
> I really need help on this. Firefox will not sync my passwords to the
> computer I am on right now. If I put passwords in manually it will only keep
> them until I turn the computer off.  This is really causing problems and I
> need help, PLEASE

Bill, if you can follow the procedure at https://wiki.mozilla.org/Toolkit:Password_Manager/Debugging and attach the logs to this bug, it might give us some more insights into what is going wrong (it doesn't sound like *exactly* this bug, because with this bug it should be possible to create new passwords locally. It's more likely to be something around bug 1295122 - but these logs will help us know for sure)

Comment 20

[Bill]

Mark, I think I found the logs, but I have no idea if this is what you want. There are a bunch of these and I have no idea how to attach them here.  I can copy them to a word doc, but no idea how to attach the doc. 
I need very detailed instructions as i said before.  I really appreciate your help, just need detailed instructions.
Thanks
Bill


(In reply to Mark Hammond [:markh] from comment #19)
> (In reply to Bill from comment #18)
> > I really need help on this. Firefox will not sync my passwords to the
> > computer I am on right now. If I put passwords in manually it will only keep
> > them until I turn the computer off.  This is really causing problems and I
> > need help, PLEASE
> 
> Bill, if you can follow the procedure at
> https://wiki.mozilla.org/Toolkit:Password_Manager/Debugging and attach the
> logs to this bug, it might give us some more insights into what is going
> wrong (it doesn't sound like *exactly* this bug, because with this bug it
> should be possible to create new passwords locally. It's more likely to be
> something around bug 1295122 - but these logs will help us know for sure)

Comment 21

[Mark Hammond [:markh] [:mhammond]]

Thanks Bill. It would be best if you could find "notepad" on your computer, paste the logs in there, then save the file somewhere convenient.  Then, in this bug in Bugzilla, look for the "Attach File" link where the other 3 existing attachments are shown, and select this new file to upload. Let me know if you get stuck.

Comment 22

[Bill]

Mark, again I need detailed instructions, please.  I have no idea how to copy a page to notepad or how to attach to the bug.  I know it sounds easy to you, but it's greek to me.
Thanks again for the help. Is it possible for you to take the email I sent with the logs and put it into the bug?

Bill

Comment 23

[Mark Hammond [:markh] [:mhammond]]

Sending me the logs via email is fine, thanks (if you already sent it, it hasn't arrived as yet)

Comment 24

[Mark Hammond [:markh] [:mhammond]]

Bill sent me logs via email (thanks!) and while they aren't complete, it appears as though he is getting "Failed to decrypt string ... (NS_ERROR_FAILURE) even when attempting to manually save passwords. So sadly this patch will not fix this specific issue and the problem Bill is seeing is something else around "key3.db is corrupt". I suspect this would be fixed by deleting key3.db and logins.json, although that's a relatively technical and risky step to take.

(And while I'm here: Matt, it would be great if you could take another look at the patch and my response to your initial review :)

Comment 25

[Matthew N. [:MattN]]

Comment on attachment 8883850 [details]
Bug 621846 - allow an unencryptable login with a GUID to be replaced by an item with the same GUID.

https://reviewboard.mozilla.org/r/154798/#review212058

Comment 26

[Mark Hammond [:markh] [:mhammond]]

Comment on attachment 8883850 [details]
Bug 621846 - allow an unencryptable login with a GUID to be replaced by an item with the same GUID.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/154798/diff/1-2/

Comment 27

[Mark Hammond [:markh] [:mhammond]]

Comment on attachment 8883850 [details]
Bug 621846 - allow an unencryptable login with a GUID to be replaced by an item with the same GUID.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/154798/diff/2-3/

Comment 28

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/39b5df4d5450
allow an unencryptable login with a GUID to be replaced by an item with the same GUID. r=MattN

Comment 29

[Cosmin Sabou [:CosminS]]

https://hg.mozilla.org/mozilla-central/rev/39b5df4d5450

Comment 30

[Bill]

Does any of this mean my firefox will sync across to my tablet now?

Comment 31

[Mark Hammond [:markh] [:mhammond]]

(In reply to Bill from comment #30)
> Does any of this mean my firefox will sync across to my tablet now?

Unfortunately, I don't think it will, as it seems the problems you are having are more than just syncing - you also aren't able to store passwords locally regardless of Sync. It's possible that deleting logins.json and key3.db from your profile directory when Firefox isn't running would fix things, but that's a somewhat risky and advanced process.

Comment 32

[Bill]

Okay, so are you telling me that firefox will not work correctly on my surface pro? What if I uninstalled firefox and re-installed it. Sure seems like this ought to work??????????