516338 - login credentials retrieval Javascript sometimes so slow it times out.

Status: RESOLVED DUPLICATE of bug 492197

(Toolkit :: Password Manager, defect)

Description

[John Nagle]

User-Agent:       Mozilla/5.0 (Windows; U; Windows NT 5.0; en-US; rv:1.9.1.2) Gecko/20090729 Firefox/3.5.2
Build Identifier: Mozilla/5.0 (Windows; U; Windows NT 5.0; en-US; rv:1.9.1.2) Gecko/20090729 Firefox/3.5.2

When a page with stored login credentials is loaded, the Javascript involved sometimes takes up to a minute before it will allow the page to load.  
The Javascript dialog ("A script on this page is taking too long...") appears.

Seen with logins to Slashdot, Facebook, Groklaw, etc. 

Caught the situation with the Venkman debugger.  Javascript seems to be
spending most of the time in this code: 


storage-mozStorage.js
...
     		// The specified login isn't encrypted, so we need to ensure
     815         // the logins we're comparing with are decrypted. We decrypt one entry
     816         // at a time, lest _decryptLogins return fewer entries and screw up
     817         // indices between the two.
 -   818         for (let i = 0; i < logins.length; i++) {
     819             let [[decryptedLogin], userCanceled] =
 -   820                         this._decryptLogins([logins[i]]);	


I don't understand the internals enough to fix this, but it looks like there's a linear search in something that ought to be a database search.  Look for an O(N^2) problem. 

Reproducible: Sometimes

Steps to Reproduce:
Reproduces for me simply by navigating to "facebook.com", or "groklaw.net", but only when those pages have not been accessed within hours.  Once the page has been accessed, there's no delay.  So there's some relationship with some cached information here.
Actual Results:  
If I click "Continue" on the "Javascript taking too long" dialog, after about three or four tries, the Javascript finishes and the proper login info is filled in.


Notes:
1.  Running on Windows 2000.
2.  This instance of Firefox prefs was upgraded from Firefox 2, from Firefox 1, 
and previously imported from Netscape 4.  If something is doing a linear search through an entire database, that may be the problem. 
3.  Default theme.
4.  Greasemonkey installed, but problem occurs with Greasemonkey disabled.
5.  Venkman debugger installed, but problem occurs with or without debugger.

Comment 1

[Justin Dolske [:Dolske]]

Roughly many logins do you have stored (total / for these sites)?

If you've carried your password database for so long, it's quite possible that there are a corrupted entries that don't show up. One way to check would be by looking at the DB with the sqlite3 utility or the SQLite Manager addon (https://addons.mozilla.org/en-US/firefox/addon/5817).

You can also try turning on debugging (see https://wiki.mozilla.org/Firefox:Password_Manager_Debugging) and see what, if anything, is reported during the hang.

Comment 2

[John Nagle]

Here's the password manager debug log for a Facebook login.  This took over a minute to complete.  

PwMgr mozStorage: Failed to decrypt string: http://pub176.ezboard.com (NS_ERROR_ILLEGAL_VALUE)
{Many reps]
PwMgr mozStorage: Failed to decrypt string: http://sanfrancisco.tribe.net (NS_ERROR_ILLEGAL_VALUE)
PwMgr mozStorage: Creating new statement for query: SELECT * FROM moz_logins WHERE (hostname = :hostname) AND (httpRealm isnull)
PwMgr mozStorage: _searchLogins: returning 3 logins
PwMgr mozStorage: Creating new statement for query: UPDATE moz_logins SET hostname = :hostname, httpRealm = :httpRealm, formSubmitURL = :formSubmitURL, usernameField = :usernameField, passwordField = :passwordField, encryptedUsername = :encryptedUsername, encryptedPassword = :encryptedPassword, guid = :guid, encType = :encType WHERE id = :id
PwMgr mozStorage: _searchLogins: returning 70 logins
[Many repetitions]
PwMgr mozStorage: _searchLogins: returning 27 logins
[Many repetitions]
PwMgr mozStorage: _searchLogins: returning 7 logins
[Many repetitions]
PwMgr mozStorage: _searchLogins: returning 291 logins
[Many repetitions]
PwMgr mozStorage: _findLogins: returning 2 logins
Login Manager: found 2 matching logins.
Login Manager: attaching autocomplete stuff
Login Manager: Multiple logins for form, so not filling any.
Login Manager: _fillDocument processing form[1]
Login Manager: Searching for logins matching host: http://www.facebook.com, formSubmitURL: https://register.facebook.com, httpRealm: null
PwMgr mozStorage: _searchLogins: returning 1 logins
PwMgr mozStorage: _findLogins: returning 1 logins
Login Manager: found 1 matching logins.
Login Manager: attaching autocomplete stuff
PwMgr mozStorage: _searchLogins: returning 2 logins
PwMgr mozStorage: _findLogins: returning 2 logins
Login Manager: found 2 matching logins.
Login Manager: attaching autocomplete stuff
Login Manager: Password not filled. None of the stored logins match the username already present.
Login Manager: onStateChange accepted: req = about:blank, flags = 0x30004
Login Manager: domEventListener: got event DOMContentLoaded

Comment 3

[Justin Dolske [:Dolske]]

Does this only happen the first time you visit some page with a password, after which it runs fine (until the next restart)?

This is almost certainly the same problem as bug 492197. The top part of you log looks very much like we're doing the base64 reencryption, and failures trigger the 492197 problem.

A couple workarounds:

1) Delete signons.sqlite and signons*.txt from your profile. This will nuke all your existing logins, so you might not want to do this. But it's simple! :)

2) Use the Password Exporter extension (https://addons.mozilla.org/en-US/firefox/addon/2848) to save a backup of your logins. Then do the stuff from workaround #1. Then import your logins with the extension. Do you see duplicate logins in Tools --> Options --> Security, "View Passwords"? If so, you'll need to delete the extras before doing any of this.

Comment 4

[John Nagle]

Went into the SQL database with SQLite Manager, and cleaned out about 200 old password entries, including most of the ones mentioned in error messages. 
The database had about 600 entries; now it has 400. 
Performance seems to have improved considerably.

But irrelevant entries for other sites shouldn't be slowing down credentials retrieval. That's what the database is for.  Something is looking at irrelevant entries, slowly.

I suspect that entries which produce the message:
PwMgr mozStorage: Failed to decrypt string: http://pub176.ezboard.com
(NS_ERROR_ILLEGAL_VALUE)
are handled very slowly, and time is being spent on entries that are irrelevant to the current operation.

Comment 5

[John Nagle]

After looking at bug 492197, I agree that this bug is probably related.

Comment 6

[Justin Dolske [:Dolske]]

Let's just dupe this.