492197 - password manager is extremely slow at reencrypting base64-encoded signons

Status: RESOLVED FIXED

(Toolkit :: Password Manager, defect)

Description

[gekacheka]

User-Agent:       Mozilla/5.0 (Windows; U; Windows NT 5.0; en-US; rv:1.9.1b5pre) Gecko/20090509 Shiretoko/3.5b5pre
Build Identifier: Mozilla/5.0 (Windows; U; Windows NT 5.0; en-US; rv:1.9.1b5pre) Gecko/20090509 Shiretoko/3.5b5pre

Unresponsive script warning appears when I try to log in to bugzilla.
Won't let me log in unless I stop script.

"Continue" does not help... tried continuing 50 times still never finishes.
"Don't show this dialog again" does not help, waited many minutes, had to terminate Firefox process from task manager.
"Stop script" stops the script, but the login and password are not autofilled.
(May take 3 times to stop everything.  Was able to log in manually.)

Workaround: after stop script, reload page, and the autofill succeeds.


Reproducible: Sometimes

Steps to Reproduce:
Happens every time I restart firefox (shiretoko) with my default profile, 
and try to log in to bugzilla.
- does not happen on subsequent log-ins in same session (without exit FF).
- does not happen on a new profile.
- does not happen on other sites (e.g., yahoo).

0. (previously logged in to bugzilla, so id is in password manager)
1. logout of bugilla, so not currently logged in.
2. Restart firefox.
3. go to bugzilla login page
https://bugzilla.mozilla.org/?GoAheadAndLogIn=1

Actual Results:  
Unresponsive script dialog appears.  After continuing 50 times, still appears.


Expected Results:  
login and password are autofilled (immediately).

(This happens if I stop the script and reload page.)

Sample of 50 Unresponsive script warnings (continuing each):

4x components/storage-mozStorage.js:473
1x modules/XPCOMUtils.jsm:260
2x components/storage-mozStorage.js:473
1x components/nsLoginInfo.js:79
9x components/storage-mozStorage.js:473
1x components/nsLoginInfo.js:79
3x components/storage-mozStorage.js:473
1x modules/XPCOMUtils.jsm:260
1x components/nsLoginInfo.js:79
2x components/storage-mozStorage.js:604
2x components/storage-mozStorage.js:473
1x components/storage-mozStorage.js:604
1x components/nsLoginInfo.js:79
1x modules/XPCOMUtils.jsm:262
1x components/storage-mozStorage.js:473
1x components/storage-mozStorage.js:604
1x components/nsLoginInfo.js:79
1x modules/XPCOMUtils.jsm:260
2x components/storage-mozStorage.js:473
1x modules/XPCOMUtils.jsm:259
1x components/nsLoginInfo.js:79
1x components/storage-mozStorage.js:473
1x components/storage-mozStorage.js:604
1x modules/XPCOMUtils.jsm:260
1x modules/XPCOMUtils.jsm:265
1x components/storage-mozStorage.js:473
2x components/storage-mozStorage.js:604
2x components/storage-mozStorage.js:473
1x components/nsLoginInfo.js:79
1x modules/XPCOMUtils.jsm:259
1x components/nsLoginInfo.js:79

Comment 1

[Matthias Versen [:Matti]]

>- does not happen on a new profile.

Does it happen in the Firefox safemode ?
- http://support.mozilla.com/en-US/kb/Safe+Mode

Comment 2

[gekacheka]

(In reply to comment #1)
> >- does not happen on a new profile.
> 
> Does it happen in the Firefox safemode ?
> - http://support.mozilla.com/en-US/kb/Safe+Mode

Yes, this problem still happens in safe-mode.  (Thanks for reminding me to check.)

Comment 3

[Matthias Versen [:Matti]]

You can only check your old profile for a corrupt file.
I would try to remove the places.sqlite first as test (don't delete it) and would do that for all sqlite files until you have found the file that is causing this.

Comment 4

[Justin Dolske [:Dolske]]

(In reply to comment #0)

> Sample of 50 Unresponsive script warnings (continuing each):

Where are you getting this data from?

> 4x components/storage-mozStorage.js:473

That's in modifyLogin(), which is odd because basically the only time this would be called is after you confirm a password change.

I'd be curious to see some debug output from when this happens. See https://wiki.mozilla.org/Firefox:Password_Manager_Debugging

How many logins do you have saved? How large is the signons.sqlite in your profile?

Comment 5

[Justin Dolske [:Dolske]]

(In reply to comment #3)
> You can only check your old profile for a corrupt file.

If it's a DB issue, it's probably signons.sqlite and not places. Do keep a backup of the file, as we might need to examine it to figure out what happened (so we can prevent this from happening for other users).

Comment 6

[gekacheka]

(In reply to comment #3)

Apparently it is not the sqlite files.  

After making a copy of my profile, I deleted the .sqlite files individually one by one (exit FF, delete file, restart FF), still the same.  I then deleted all of the regenerated .sqlite files at once.  Still the same.  I then deleted all the .sqlite files and .sqlite-journal files that remained (and storage.sdb for good measure).  Still the same.

Comment 7

[gekacheka]

Attachment: Error console log with prefs signon.debug=true and javascript.options.showInConsole=true.

(In reply to comment #4)
> (In reply to comment #0)
> 
> > Sample of 50 Unresponsive script warnings (continuing each):
> 
> Where are you getting this data from?

Writing down the text of the "Warning: Unresponsive script" dialog.
4x means it occurred 4 times in a row in that run.
 
> I'd be curious to see some debug output from when this happens. See
> https://wiki.mozilla.org/Firefox:Password_Manager_Debugging

See attachment.

> 
> How many logins do you have saved? 

Looking in Tools > Options > Security > Saved Passwords
~74-76 that look ok (two have blank username column).
There seem to be hundreds more for two 'sites', both with urls of the form 
mailbox://[e-mail]/
All entries with these two 'sites' have blank username column.
The email addresses are old, maybe from a migration from MozSuite or Netscape.

> How large is the signons.sqlite in your profile?

587KB

Comment 8

[Justin Dolske [:Dolske]]

Ok, so, the modifyLogin call is a result bug 316084, where we added code to reencrypt old base64-encoded logins. Normally this only happens once in a profile, since it shows up here it's probably happening every time you launch the browser. It's possible the reencryption just isn't finishing, but I suspect it's a bit broken...

The modifyLogin() call doesn't really work when there are duplicate logins. It finds the first matching login and modifies it. So, the reencryption step ends up changing the same login over and over, and never modifies the others. This isn't so much a bug in modifyLogin as a bug in whatever added duplicate logins in the first place. It's a known limitation of the API.

The pile of "PwMgr mozStorage: _searchLogins: returning 891 logins" confused me, until I realized that _getIdForLogin() [which modifyLogin() uses] is implemented on top of _searchLogins() now. There are 1600 logins we're trying to modify, so doing that for each one ends up being terribly inefficient.

The immediate fix is for you to delete all those duplicate mailbox:// logins.

We could make the process more efficient by changing reencryptBase64Logins() to make use of the login GUIDs that it gets from the searchLogins({ encType: 0 }) call. Instead of calling modifyLogin, just have it reencrypt the username/password, and execute a statement to explicitly change just that. And maybe just process 100 at a time.

Comment 9

[Justin Dolske [:Dolske]]

Oh, and I think there's a separate JS engine bug here in that chrome code isn't supposed to ever trigger the slow script dialog. Even though it was helpful for debugging in this case. :)

Comment 10

[gekacheka]

Ok, from the Saved Password dialog I deleted all the entries for the two
mailbox://[e-mail]/ urls.  The good news is that the bugzilla
username and password is now autofilling on the first try from a restarted
firefox.

Thanks for the help!  I'd be satisfied with resolving to WorksForMe, but I'll leave it up to you if you want to use this bug to make changes. 

(Details: After shift-selecting all the mailbox: urls in the Saved Passwords
dialog and clicking remove, it took about an hour.  It caused similar
Unresponsive script warnings to appear every 20 to 30secs.  Fortunately with
the pref settings, the error console log messages showed progress, counting
down about 15 between each dialog, so I kept hitting continue.  Note the
countdown goes from 891 down to 1 then restarts at 643 and goes to 1.  I am not
sure what that means, maybe it is the number of entries for each of
the two mailbox: urls.

Login Manager: Removing login: [xpconnect wrapped nsILoginInfo]
PwMgr mozStorage: _searchLogins: returning 891 logins
PwMgr mozStorage: Creating new statement for query: DELETE FROM moz_logins
WHERE id = :id
Login Manager: Removing login: [xpconnect wrapped nsILoginInfo]
PwMgr mozStorage: _searchLogins: returning 890 logins
Login Manager: Removing login: [xpconnect wrapped nsILoginInfo]
PwMgr mozStorage: _searchLogins: returning 889 logins
Login Manager: Removing login: [xpconnect wrapped nsILoginInfo]
PwMgr mozStorage: _searchLogins: returning 888 logins
...
Login Manager: Removing login: [xpconnect wrapped nsILoginInfo]
PwMgr mozStorage: _searchLogins: returning 876 logins

  [Warning: Unresponsive script ... modules/XPCOMUtils.jsm:260: clicked
'Continue']

Login Manager: Removing login: [xpconnect wrapped nsILoginInfo]
PwMgr mozStorage: _searchLogins: returning 875 logins
Login Manager: Removing login: [xpconnect wrapped nsILoginInfo]
PwMgr mozStorage: _searchLogins: returning 874 logins
Login Manager: Removing login: [xpconnect wrapped nsILoginInfo]
PwMgr mozStorage: _searchLogins: returning 873 logins

  [[countdown continues, dialog appears about every 15.
    other files that appear:
         components/storage-mozStorage.js:368
         components/storage-mozStorage.js:604
   ]]

...
PwMgr mozStorage: _searchLogins: returning 3 logins
Login Manager: Removing login: [xpconnect wrapped nsILoginInfo]
PwMgr mozStorage: _searchLogins: returning 2 logins
Login Manager: Removing login: [xpconnect wrapped nsILoginInfo]
PwMgr mozStorage: _searchLogins: returning 1 logins
Login Manager: Removing login: [xpconnect wrapped nsILoginInfo]
PwMgr mozStorage: _searchLogins: returning 643 logins
Login Manager: Removing login: [xpconnect wrapped nsILoginInfo]
PwMgr mozStorage: _searchLogins: returning 642 logins
Login Manager: Removing login: [xpconnect wrapped nsILoginInfo]
PwMgr mozStorage: _searchLogins: returning 641 logins
Login Manager: Removing login: [xpconnect wrapped nsILoginInfo]
...
PwMgr mozStorage: _searchLogins: returning 3 logins
Login Manager: Removing login: [xpconnect wrapped nsILoginInfo]
PwMgr mozStorage: _searchLogins: returning 2 logins
Login Manager: Removing login: [xpconnect wrapped nsILoginInfo]
PwMgr mozStorage: _searchLogins: returning 1 logins
)

Comment 11

[gekacheka]

An additional benefit: much faster startup and shutdown times.  Prior to removing the duplicate passwords, both startup and shutdown times could be measured in minutes, now it is in seconds.

Comment 12

[Justin Dolske [:Dolske]]

(In reply to comment #10)

> Thanks for the help!  I'd be satisfied with resolving to WorksForMe, but I'll
> leave it up to you if you want to use this bug to make changes. 

We'll leave it open to look at changing the code that made things slow.

> (Details: After shift-selecting all the mailbox: urls in the Saved Passwords
> dialog and clicking remove, it took about an hour.

Yikes! removeLogin() works similarly, so it's not too surprising in the context of the previous problem.

What kind of hardware are you running on? (new/old system? ram?) I wouldn't have expected things to be nearly that slow, even with the inefficient code.

> Note the
> countdown goes from 891 down to 1 then restarts at 643 and goes to 1.  I am not
> sure what that means, maybe it is the number of entries for each of
> the two mailbox: urls.

Correct.

Comment 13

[Paul O'Shannessy [:zpao] (not bugmail, email directly)]

Attachment: Patch v0.1 (WIP)

WIP from today. This is attacking 3 points where we can optimize with large data sets (like we did for import). #1 & #2 involve wrapping each migration in a transaction. #3 involves cutting out the use of _modifyLogin when reencrypting base64 logins and creating the statement ourselves (thus reducing the number of queries by half & doesn't involve additional QIing).

I didn't actually run any tests to see if this code runs yet. I also need to see if this actually does improve performance (it *should*). I can probably modify the perf tests from bug 288040 for that.

Comment 14

[gekacheka]

1. Tried the patch (attachment 377807 [details] [diff] [review]) on my old signons.sqlite and it does fix the original problem so the unresponsive script warning does not appear (and removing the fix makes it appear again).  Thanks; I hope this bug is approved for 1.9.1.

2. The patch does not fix the similar problem with removing a large number of passwords detailed in comment 10.  Should I file a separate bug for that?

3. FYI, the hundreds of entries that appear to be duplicate in the Saved Passwords dialog also appear to be duplicate in SQLite Manager (they differ only in id and guid columns).  (In signons2.txt and signons3.txt they appear as the mailbox: 'site' name line followed by hundreds of duplicate 5-line entries.)

Comment 15

[Justin Dolske [:Dolske]]

Comment on attachment 377807 [details] [diff] [review]
Patch v0.1 (WIP)

>             let [logins, ids] = this._searchLogins({ encType: 0 });
...
>             [logins, userCanceled] = this._decryptLogins(logins);
...
>+            for (let i = 0; i < logins.length; i++) {
...
>+                let query =
>+                    "UPDATE moz_logins " +
>+                    "SET encryptedUsername = :encryptedUsername, " +
>+                        "encryptedPassword = :encryptedPassword, " +
>+                        "encType = :encType "
>+                    "WHERE id = :id";

I think you'll need to use the GUID in the where-clause, instead of the id. decryptLogins() can return fewer logins than are passed in, if it's unable to decrypt some. Although, hmm, I wonder if that can happen with base64 data. I guess it can, if there's an invalid input?

>+            //XXXzpao we should _sendNotification here?

Probably not? We don't notify on initial import either...

>+        this._dbConnection.beginTransaction();
...
>+        this._dbConnection.commitTransaction();

Don't need these around each version migration. There's already a single transaction wrapping all of them, in _dbMigrate().

Comment 16

[Justin Dolske [:Dolske]]

Updating summary; with recent fixes (eg bug 492410) there won't be a slow-script dialog, just a long pause/hang.

Comment 17

[Paul O'Shannessy [:zpao] (not bugmail, email directly)]

Comment on attachment 377807 [details] [diff] [review]
Patch v0.1 (WIP)

>-            for each (let login in logins)
>-                this.modifyLogin(login, login);
>+            let encUsername, encPassword, stmt;
>+            for (let i = 0; i < logins.length; i++) {
>+                [encUsername, encPassword, userCanceled] = this._encryptLogin(login);

So this shouldn't have actually even been doing things properly seeing as |login| isn't defined...

(In reply to comment #15)
> I think you'll need to use the GUID in the where-clause, instead of the id.
> decryptLogins() can return fewer logins than are passed in, if it's unable to
> decrypt some. Although, hmm, I wonder if that can happen with base64 data. I
> guess it can, if there's an invalid input?

Yea using GUID is probably better here. Each login should already be QI'ed to LoginMetaInfo (in _searchLogins) and have .guid

Comment 18

[Justin Dolske [:Dolske]]

zpao: Can you finish up this patch?

Comment 19

[Paul O'Shannessy [:zpao] (not bugmail, email directly)]

(In reply to comment #18)
> zpao: Can you finish up this patch?

I can and will. Since I'm out of town right now I'll target early next week.

Comment 21

[Paul O'Shannessy [:zpao] (not bugmail, email directly)]

Currently blocked by bug 517500, so progress is stalled. In theory the patch I have (which is basically the patch here + changes from comment 15) should work.

Comment 22

[Paul O'Shannessy [:zpao] (not bugmail, email directly)]

Attachment: Patch v0.2

Turns out I was just really dumb. Here's the patch. I might be going a bit overkill with the try-catches but thought it better to continue past single failures & only rollback if there's a larger failure (that & the try-catch-finally around createstatement/execute/reset is how every other query is done.

I haven't actually tested speed here, but anecdotal evidence supports it. As does the fact that we're doing the query directly instead of relying on modifyLogin & additional queries.

Comment 23

[John Nagle]

If there aren't supposed to be duplicates in the "moz_logins" table of the SQLite database, the SQL table definition should have a UNIQUE INDEX clause to enforce that.  It doesn't.  There are five indices, but they all allow duplicates.
I think the database CREATE statement needs "UNIQUE INDEX(hostname, usernameField)" added.  

Let the database enforce the entry uniqueness requirement. That's what it's for.

Comment 24

[Justin Dolske [:Dolske]]

That's not an option, because we're dealing with legacy data that may contain duplicates.

Comment 25

[Justin Dolske [:Dolske]]

Comment on attachment 401884 [details] [diff] [review]
Patch v0.2

>+        this._dbConnection.beginTransaction();

Hrm, I kind of want to move this (and the commit) closer to just the for-loop, but the possibility of the encrypt throwing ends up making that messy. Oh well.

>         try {
>             let [logins, ids] = this._searchLogins({ encType: 0 });

Please change this to ENCTYPE_BASE64? Guess we missed this one last time around.

>+                } catch (e) {
>+                    // Ignore singular errors, continue trying to update others.

Toss a log() in here, so if it ever happens we can see what hapopened.

Comment 26

[Paul O'Shannessy [:zpao] (not bugmail, email directly)]

Pushed http://hg.mozilla.org/mozilla-central/rev/1f8406ba3d51

Comment 27

[Paul O'Shannessy [:zpao] (not bugmail, email directly)]

Attachment: Patch v1.0 (as checked in)

As checked in with nits from Dolske.

Requesting a1.9.2 since this is an occasional perf issue introduced in Firefox 3.5. It will also help keep central & branch in sync.

Comment 28

[:Gavin Sharp [email: [e-mail]]]

Comment on attachment 403294 [details] [diff] [review]
Patch v1.0 (as checked in)

approval1.9.2 requests aren't currently being monitored, since we're nearing RC freeze and there are too many outstanding requests, so I'm clearing this request. Feel free to re-request approval if you are confident that it's worth drivers' time to consider whether this non-blocker needs to land for 1.9.2 at this stage.

Comment 29

[Justin Dolske [:Dolske]]

Comment on attachment 403294 [details] [diff] [review]
Patch v1.0 (as checked in)

I think this is worth taking on both 1.9.2 and 1.9.1. It's tested, and for people who are *not* experiencing the perf issues it's nearly a no-op... The common case is that this code does its processing once, and converts *all* base64 logins, and never has work to do in the future (ie, bails out at the top of the loop). People with perf issues are having logins that don't get converted for whatever reason, and this code gets run one per session.

Comment 30

[Mike Beltzner [:beltzner, not reading bugmail]]

Comment on attachment 403294 [details] [diff] [review]
Patch v1.0 (as checked in)

a192=beltzner

Comment 31

[Justin Dolske [:Dolske]]

Pushed to 192: http://hg.mozilla.org/releases/mozilla-1.9.2/rev/e682c3ddf841

Comment 32

[Daniel Veditz [:dveditz]]

Comment on attachment 403294 [details] [diff] [review]
Patch v1.0 (as checked in)

Approved for 1.9.1.8, a=dveditz for release-drivers

Comment 33

[Paul O'Shannessy [:zpao] (not bugmail, email directly)]

Pushed to 191 http://hg.mozilla.org/releases/mozilla-1.9.1/rev/e81fd8ff76d2