1240278 - parser error stops syncing passwords/logins

Status: NEW

(Firefox :: Sync, defect, P5)

Description

[rumburake]

User Agent: Mozilla/5.0 (Windows NT 6.3; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/47.0.2526.111 Safari/537.36

Steps to reproduce:

1. In Firefox for Windows, I have a saved login like:
 - Site: http://10.111.211.91:8080
 - User: foo
 - Pass: boo
The password is imported from Chrome. I sync everything this to Firefox Accounts.
2. In Firefox for Android I sync from Firefox Accounts to get this Login

Tried with Firefox for Android 43, 44, on 2 Lollipop 5.0 devices (Arm and Intel).



Actual results:

Parser error which also stops the sync of all other passwords. If I have many passwords as well, only the ones before this error are synced. Here is the Android log:
W/FxAccounts( 9759): firefox :: RecordsChannel :: onFetchFailed. Calling for immediate stop.
W/FxAccounts( 9759): java.lang.NumberFormatException: Invalid long: "18446732429235952000"
W/FxAccounts( 9759):    at java.lang.Long.invalidLong(Long.java:124)
W/FxAccounts( 9759):    at java.lang.Long.parse(Long.java:366)
W/FxAccounts( 9759):    at java.lang.Long.parseLong(Long.java:353)
W/FxAccounts( 9759):    at java.lang.Long.parseLong(Long.java:321)
W/FxAccounts( 9759):    at java.lang.Long.valueOf(Long.java:511)
W/FxAccounts( 9759):    at org.json.simple.parser.Yylex.yylex(Yylex.java:660)
W/FxAccounts( 9759):    at org.json.simple.parser.JSONParser.parse$66bc622e(JSONParser.java:118)
W/FxAccounts( 9759):    at org.mozilla.gecko.sync.ExtendedJSONObject.parseRaw(ExtendedJSONObject.java:54)
W/FxAccounts( 9759):    at org.mozilla.gecko.sync.ExtendedJSONObject.<init>(ExtendedJSONObject.java:213)
W/FxAccounts( 9759):    at org.mozilla.gecko.sync.ExtendedJSONObject.<init>(ExtendedJSONObject.java:222)
W/FxAccounts( 9759):    at org.mozilla.gecko.sync.ExtendedJSONObject.parseJSONObject(ExtendedJSONObject.java:152)
W/FxAccounts( 9759):    at org.mozilla.gecko.sync.ExtendedJSONObject.parseUTF8AsJSONObject(ExtendedJSONObject.java:165)
W/FxAccounts( 9759):    at org.mozilla.gecko.sync.CryptoRecord.decrypt(CryptoRecord.java:200)
W/FxAccounts( 9759):    at org.mozilla.gecko.sync.middleware.Crypto5MiddlewareRepositorySession$DecryptingTransformingFetchDelegate.onFetchedRecord(Crypto5MiddlewareRepositorySession.java:97)
W/FxAccounts( 9759):    at org.mozilla.gecko.sync.repositories.Server11RepositorySession$RequestFetchDelegateAdapter.handleWBO(Server11RepositorySession.java:191)
W/FxAccounts( 9759):    at org.mozilla.gecko.sync.net.WBOCollectionRequestDelegate.handleRequestProgress(WBOCollectionRequestDelegate.java:29)
W/FxAccounts( 9759):    at org.mozilla.gecko.sync.net.SyncStorageCollectionRequest$SyncCollectionResourceDelegate.handleHttpResponse(SyncStorageCollectionRequest.java:113)
W/FxAccounts( 9759):    at org.mozilla.gecko.sync.net.BaseResource.execute(BaseResource.java:309)
W/FxAccounts( 9759):    at org.mozilla.gecko.sync.net.BaseResource.go(BaseResource.java:340)
W/FxAccounts( 9759):    at org.mozilla.gecko.sync.net.BaseResource.get(BaseResource.java:346)
W/FxAccounts( 9759):    at org.mozilla.gecko.sync.net.SyncStorageRequest.get(SyncStorageRequest.java:180)
W/FxAccounts( 9759):    at org.mozilla.gecko.sync.repositories.Server11RepositorySession.fetchSince(Server11RepositorySession.java:285)
W/FxAccounts( 9759):    at org.mozilla.gecko.sync.middleware.Crypto5MiddlewareRepositorySession.fetchSince(Crypto5MiddlewareRepositorySession.java:135)
W/FxAccounts( 9759):    at org.mozilla.gecko.sync.synchronizer.RecordsChannel.flow(RecordsChannel.java:173)
W/FxAccounts( 9759):    at org.mozilla.gecko.sync.synchronizer.RecordsChannel.onBeginSucceeded(RecordsChannel.java:270)
W/FxAccounts( 9759):    at org.mozilla.gecko.sync.repositories.delegates.DeferredRepositorySessionBeginDelegate$1.run(DeferredRepositorySessionBeginDelegate.java:24)
W/FxAccounts( 9759):    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)
W/FxAccounts( 9759):    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
W/FxAccounts( 9759):    at java.lang.Thread.run(Thread.java:818)
W/FxAccounts( 9759): firefox :: SynchronizerSession :: First RecordsChannel onFlowFetchFailed. Logging remote fetch error.
W/FxAccounts( 9759): java.lang.NumberFormatException: Invalid long: "18446732429235952000"
W/FxAccounts( 9759):    at java.lang.Long.invalidLong(Long.java:124)
W/FxAccounts( 9759):    at java.lang.Long.parse(Long.java:366)
W/FxAccounts( 9759):    at java.lang.Long.parseLong(Long.java:353)
W/FxAccounts( 9759):    at java.lang.Long.parseLong(Long.java:321)
W/FxAccounts( 9759):    at java.lang.Long.valueOf(Long.java:511)
W/FxAccounts( 9759):    at org.json.simple.parser.Yylex.yylex(Yylex.java:660)
W/FxAccounts( 9759):    at org.json.simple.parser.JSONParser.parse$66bc622e(JSONParser.java:118)
W/FxAccounts( 9759):    at org.mozilla.gecko.sync.ExtendedJSONObject.parseRaw(ExtendedJSONObject.java:54)
W/FxAccounts( 9759):    at org.mozilla.gecko.sync.ExtendedJSONObject.<init>(ExtendedJSONObject.java:213)
W/FxAccounts( 9759):    at org.mozilla.gecko.sync.ExtendedJSONObject.<init>(ExtendedJSONObject.java:222)
W/FxAccounts( 9759):    at org.mozilla.gecko.sync.ExtendedJSONObject.parseJSONObject(ExtendedJSONObject.java:152)
W/FxAccounts( 9759):    at org.mozilla.gecko.sync.ExtendedJSONObject.parseUTF8AsJSONObject(ExtendedJSONObject.java:165)
W/FxAccounts( 9759):    at org.mozilla.gecko.sync.CryptoRecord.decrypt(CryptoRecord.java:200)
W/FxAccounts( 9759):    at org.mozilla.gecko.sync.middleware.Crypto5MiddlewareRepositorySession$DecryptingTransformingFetchDelegate.onFetchedRecord(Crypto5MiddlewareRepositorySession.java:97)
W/FxAccounts( 9759):    at org.mozilla.gecko.sync.repositories.Server11RepositorySession$RequestFetchDelegateAdapter.handleWBO(Server11RepositorySession.java:191)
W/FxAccounts( 9759):    at org.mozilla.gecko.sync.net.WBOCollectionRequestDelegate.handleRequestProgress(WBOCollectionRequestDelegate.java:29)
W/FxAccounts( 9759):    at org.mozilla.gecko.sync.net.SyncStorageCollectionRequest$SyncCollectionResourceDelegate.handleHttpResponse(SyncStorageCollectionRequest.java:113)
W/FxAccounts( 9759):    at org.mozilla.gecko.sync.net.BaseResource.execute(BaseResource.java:309)
W/FxAccounts( 9759):    at org.mozilla.gecko.sync.net.BaseResource.go(BaseResource.java:340)
W/FxAccounts( 9759):    at org.mozilla.gecko.sync.net.BaseResource.get(BaseResource.java:346)
W/FxAccounts( 9759):    at org.mozilla.gecko.sync.net.SyncStorageRequest.get(SyncStorageRequest.java:180)
W/FxAccounts( 9759):    at org.mozilla.gecko.sync.repositories.Server11RepositorySession.fetchSince(Server11RepositorySession.java:285)
W/FxAccounts( 9759):    at org.mozilla.gecko.sync.middleware.Crypto5MiddlewareRepositorySession.fetchSince(Crypto5MiddlewareRepositorySession.java:135)
W/FxAccounts( 9759):    at org.mozilla.gecko.sync.synchronizer.RecordsChannel.flow(RecordsChannel.java:173)
W/FxAccounts( 9759):    at org.mozilla.gecko.sync.synchronizer.RecordsChannel.onBeginSucceeded(RecordsChannel.java:270)
W/FxAccounts( 9759):    at org.mozilla.gecko.sync.repositories.delegates.DeferredRepositorySessionBeginDelegate$1.run(DeferredRepositorySessionBeginDelegate.java:24)
W/FxAccounts( 9759):    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)
W/FxAccounts( 9759):    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
W/FxAccounts( 9759):    at java.lang.Thread.run(Thread.java:818)




Expected results:

Successful password sync of all passwords.

Comment 1

[rumburake]

I need to say again that the passwords were imported from Chrome.
I have tried an export through LastPass and the problem was gone!
So to reproduce this bug you need to import passwords from Chrome to Firefox in Windows first!

Comment 2

[Michal Stanke (Mozilla.cz) [:mstanke][:MikkCZ]]

I would say this would be Sync bug, but maybe I am wrong.

Comment 3

[Chris Karlof [:ckarlof]]

Richard, can you help triage and classify this bug?

Comment 4

[Richard Newman [:rnewman]]

All password record fields should be in milliseconds: they should be something like 1453488183460, 13 digits long. That number is 20 digits long, so it's not even in microseconds (the usual cause of this kind of bug).

There are two bugs here:

* We don't continue syncing when a password record fails. This is somewhat deliberate; after all, it resulted in you filing this bug, rather than just wondering where this particular password went.

* Something created a corrupt password record.

So let's look at the second of those.


I can think of three possible causes:

* The JSON parsing library is screwing up. This does happen occasionally. CC nalexander.
* Desktop screwed up when serializing a record. This doesn't happen often.
* Desktop screwed up when importing data from Chrome. I have no experience with this.

The best way to test this is to take a look at the cleartext of the record on the server. But first, we'll take a look at the cleartext that desktop Firefox is generating.

Steps:

* Open a privileged Browser Console. The Web Console isn't enough for this. See:

  https://developer.mozilla.org/en-US/docs/Tools/Browser_Console


* Paste the following code into the Browser Console. Make sure the URL matches the site you're finding the login for.

///
let url = "http://10.111.211.91:8080";

// Find the login and its GUID.
let logins = Services.logins.findLogins({}, url, "", "");
console.log("Found " + logins.length + " logins.");
let guid = logins[0].QueryInterface(Ci.nsILoginMetaInfo).guid;
console.log("GUID is " + guid);

let pwe = Weave.Service.engineManager.get("passwords");
let pws = pwe._store;
let local = pws.createRecord(guid, "passwords").cleartext;
console.log("Times: " + local.timeCreated + ", " + local.timePasswordChanged);
delete local.password;
delete local.passwordField;
delete local.username;
console.log("Record: " + JSON.stringify(local));
///

* Come back here and paste the logged output.


If this is malformed -- that is, one of the fields it prints is the one that Android is logging -- then the problem is on the desktop side.

If this looks good, then we'll have you check the server.

If the server looks good, then the bug is in Android Sync.

Comment 5

[Richard Newman [:rnewman]]

This is a desktop Sync bug: it's writing malformed records.

Comment 6

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

I just tried to reproduce with importing a saved bookmark from Chrome Canary. The dates all look sane. The output from Richards steps is:

> console.log("Times: " + local.timeCreated + ", " + local.timePasswordChanged);
Times: 1480381434752, 1480381434752 
> delete local.password;delete local.passwordField;delete local.username;
> console.log("Record: " + JSON.stringify(local));
Record: {"id":"{364c459f-3547-4207-99f4-046b8935b661}","hostname":"https://twitter.com","formSubmitURL":"https://twitter.com","httpRealm":null,"usernameField":"session[username_or_email]","timeCreated":1480381434752,"timePasswordChanged":1480381434752} 
undefined

and after syncing this record, the record on the server is:

{hostname: "https://twitter.com",
 formSubmitURL: "https://twitter.com", httpRealm: null, username: "<snip>"…}
 id: "{364c459f-3547-4207-99f4-046b8935b661}"
 hostname: "https://twitter.com"
 formSubmitURL: "https://twitter.com"
 httpRealm: null
 username: "<snip>"
 password: "<snip>"
 usernameField: "session[username_or_email]"
 passwordField: "session[password]"
 timeCreated: 1480381434752
 timePasswordChanged: 1480381434752
}

The function used to convert timestamps from Chrome logins appears to have landed in Firefox 11 and hasn't been changed since, and no other changes to ChromeProfileMigrator.js would seem to explain this, so I'm at a bit of a loss. Let's hope the reporter gets back to us.

Comment 7

[rumburake]

I regret I have no additional info about this. Reading the coments a few things come to mind:
 - the entries are logins (not bookmarks)
 - the first items generally work - so testing with just one record might not reproduce it
 - the long number could have been something other than a timestamp (pehaps the parser wrongly assumed that it should be a long int)
 - this bug might not happen anymore; regardless, a parser error on one record should not stop the sync of all other records

Comment 8

[Lina Butler [:lina]]

That 18446732429235952000 value is interesting; I'm really curious where it came from. JS can't reliably represent numbers above 2^53; JS dates can't represent values above 8640000000000000 milliseconds.

IIUC, we parse the creation date in http://searchfox.org/mozilla-central/rev/957458d8fa2328c2a760dbb30e7f1f1efa55b4d0/browser/components/migration/ChromeProfileMigrator.js#455. If it's invalid, I'd expect `.getTime()` to return `NaN`, which XPConnect reflects as 0 when we create the `nsILoginMetaInfo` object in http://searchfox.org/mozilla-central/rev/957458d8fa2328c2a760dbb30e7f1f1efa55b4d0/toolkit/components/passwordmgr/LoginHelper.jsm#557,567-569.

I'd like to understand how this happens, but I agree that Android could be defensive and ignore malformed password records. We can't do the same for bookmarks, but independent records should be OK.

Comment 9

[Richard Newman [:rnewman]]

(In reply to Kit Cambridge [:kitcambridge] from comment #8)

> I'd like to understand how this happens, but I agree that Android could be
> defensive and ignore malformed password records. We can't do the same for
> bookmarks, but independent records should be OK.

The reason why Android doesn't skip is that there's no error reporting, no persistent logging, and no ability to retry individual records -- if a coding error on the client or a malformed record exists, we'll never find out about it and the user will never get that record.

In general we'd prefer no malformed records and fail-fast for bug detection, even at the cost of one individual user being temporarily inconvenienced in this case.

That position would change if we had some other good way of finding problems…

Comment 10

[Lina Butler [:lina]]

(In reply to Richard Newman [:rnewman] from comment #9)
> The reason why Android doesn't skip is that there's no error reporting, no
> persistent logging, and no ability to retry individual records -- if a
> coding error on the client or a malformed record exists, we'll never find
> out about it and the user will never get that record.

That makes sense. On the one hand, stopping the sync for the entire engine is very poor UX, especially since a malformed record error is unlikely to go away on the next sync. On the other, silently skipping records isn't readily noticeable, and undermines confidence in Sync once it is noticed.

Either way, the original client doesn't have any signal that the record it uploaded was bad. This could tie in to our repair strategy, using a "fix this record" command to have the original client update the invalid field and reupload the record. Alternatively, the receiving client could just as well fix the field during download, then reupload; without the extra command.

Comment 11

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

There's no evidence that desktop is writing invalid dates here - we can re-prioritize this if more evidence appears.

Comment 12

[Nick Alexander :nalexander [he/him]]

This seems important: "The password is imported from Chrome. I sync everything this to Firefox Accounts."

Is it possible that Desktop's _importer_ is wrong, or that we're not clamping/scaling imports from Chrome?

Comment 13

[Richard Newman [:rnewman]]

(In reply to Nick Alexander :nalexander from comment #12)

> Is it possible that Desktop's _importer_ is wrong, or that we're not
> clamping/scaling imports from Chrome?

Mark looked into the Chrome connection in Comment 6.