1319742 - Webextensions without id cause the sync icon to spin forever

Status: VERIFIED FIXED

(WebExtensions :: Untriaged, defect, P1)

Description

[Vasilica Tamas, QA [:vtamas]]

[Prerequisites]:
- webextensions.storage.sync.enabled set to true
- create a new string setting identity.fxaccounts.autoconfig.uri and set it to https://stable.dev.lcip.org


[Affected versions]:
Firefox 53.0a1 (2016-11-22)
Firefox 52.0a2 (2016-11-22)


[Affected platforms]:
Windows 10 64-bit
Ubuntu 16.04 32-bit


[Steps to reproduce]:
1.Launch Firefox with profile A.
2.Go to about:preferences#sync and login using a valid FxA account. 
3.Install via about:debugging a webextension without id.
4.Force a sync.
5.Launch a second profile B and login into the Fxa using the same account.
6.Install via about:debugging the same webextension without id.
7.Force a sync.


[Expected Results]:
Sync icon stops from spinning and an error message should be displayed specifying the reasons for this failed synchronization.


[Actual Results]:
Sync icon never stops from spinning: http://screencast.com/t/Z5A86HDN1Ly


[Additional notes]:
This issue also reproduces for the following scenario:
  - In the first profile are installed only webextensions with id.
  - In the second profile are installed both types of webextensions: with and without id.

Comment 1

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

(We probably need a "WebExtensions: Sync" bugzilla component?)

There might be log-files at about:sync-log (enabling "success" logs might help - https://wiki.mozilla.org/CloudServices/Sync/File_a_desktop_bug)

Comment 2

[Andy McKay]

In this case the data will be stored in two different buckets because the data is for two different add-ons. WebExtensions without an id is a case for developers who are testing and something we should document on MDN when we document chrome.storage.sync, will add in dev-doc-needed to remind us about that.

If the continuous spinning is indicative of a problem, let's see if we can get some logs on that.

Comment 3

[Vasilica Tamas, QA [:vtamas]]

(In reply to Mark Hammond [:markh] from comment #1)
> (We probably need a "WebExtensions: Sync" bugzilla component?)
> 
> There might be log-files at about:sync-log (enabling "success" logs might
> help - https://wiki.mozilla.org/CloudServices/Sync/File_a_desktop_bug)

about:sync-log files using services.sync.log.appender.file.logOnSuccess preference set to true:

file:///C:/Users/vasilica.mihasca/AppData/Roaming/Mozilla/Firefox/Profiles/u8z7s967.ca/weave/logs/error-sync-1479987818662.txt

file:///C:/Users/vasilica.mihasca/AppData/Roaming/Mozilla/Firefox/Profiles/u8z7s967.ca/weave/logs/error-sync-1479987818785.txt

file:///C:/Users/vasilica.mihasca/AppData/Roaming/Mozilla/Firefox/Profiles/u8z7s967.ca/weave/logs/success-sync-1479988422916.txt

Comment 4

[Vasilica Tamas, QA [:vtamas]]

Attachment: sync-logs.zip

I’m attaching the accessible logs files.

Comment 5

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

The issue seems to be that the extension syncing got itself into an infinite loop. This is bad for a number of reasons, including the fact it will break Sync itself.

From one of the error logs:

> 1479980654252	Sync.Engine.Extension-Storage	INFO	Detected a new UUID. Reseting sync status for everything.
> 1479980654270	Sync.CollectionKeyManager	INFO	Setting collection keys contents. Our last modified: 0, input modified: undefined.
> 1479980654270	Sync.BulkKeyBundle	INFO	BulkKeyBundle being created for [default]
> 1479980654270	Sync.CollectionKeyManager	INFO	Processing downloaded per-collection keys.
> 1479980654270	Sync.BulkKeyBundle	INFO	BulkKeyBundle being created for a7a19c13f06fa455a4f10752915eba91b84d9d46@temporary-addon
> 1479980654270	Sync.CollectionKeyManager	INFO	Clearing collection keys...
> 1479980654270	Sync.CollectionKeyManager	INFO	Saving downloaded keys.
> 1479980654271	Sync.BulkKeyBundle	INFO	BulkKeyBundle being created for 6f3ba77c2a771f60e5c2d90a3c7a46b47d2123b7@temporary-addon
> 1479980654285	FirefoxAccounts	DEBUG	getOAuthToken enter
> 1479980654285	FirefoxAccounts	DEBUG	getOAuthToken returning a cached token
> 1479980654534	Sync.BulkKeyBundle	INFO	BulkKeyBundle being created for undefined
> 1479980654566	Sync.Engine.Extension-Storage	INFO	Detected a new UUID. Reseting sync status for everything.
and the lines above repeat forever until
> 1479987818225	Sync.Engine.Extension-Storage	ERROR	Syncing storage-sync-crypto: request failed: Error: HTTP 0; TypeError: NetworkError when attempting to fetch resource. (resource://gre/modules/services-common/kinto-http-client.js:1497:21) JS Stack trace: [e-mail]:98:7 < makeSpinningCallback/[e-mail]:168:27 < [e-mail]:234:12 < [e-mail]:46:12 < [e-mail]:166:21 < [e-mail]:689:5 < [e-mail]:321:7 < [e-mail]:168:15 < [e-mail]:1328:7 < [e-mail]:166:21 < [e-mail]:121:16 < [e-mail]:1318:12 < sync/<@service.js:1310:14 < [e-mail]:95:16 < [e-mail]:1298:5

Comment 6

[Ethan Glasser-Camp (:glasserc)]

Thanks for reporting this. I was able to reproduce this, including the scary log messages that :markh highlit. My naive attempt at writing a test didn't induce it, so I don't know what exactly is going on. Still investigating.

Comment 7

[Ethan Glasser-Camp (:glasserc)]

It looks like somehow the UUID field on a keyring got screwed up. Where previously it was a string, now it is a JS object. I have no idea how this happened. Also, continuing to debug on an existing profile seems to do something to it where it stops being an object. Not sure what's going on here either. Still investigating.

Comment 8

[Ethan Glasser-Camp (:glasserc)]

Attachment: Bug 1319742 - UUIDs should be strings, not objects,

`generateUUID()` returns an `nsID`, which is not exactly the same as a
UUID. `nsID`s can be converted to strings using `toString()`, but if
you use `JSON.stringify()`, they become `{}`. Object comparison in JS
performs identity comparison, which would be useless even if the UUIDs
were sensible, which they aren't. As a result, trying to sync keyrings
always failed, because it always seemed like UUIDs had changed, even
when they hadn't.

Because it never occurred to me that UUIDs wouldn't be strings, I
never even wrote a test for this. Correct this, and fix the test.

Thanks to :vasilica_mihasca and :markh for reporting and diagnosing this.

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

Comment 9

[Ethan Glasser-Camp (:glasserc)]

Comment on attachment 8815410 [details]
Bug 1319742 - UUIDs should be strings, not objects,

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

Comment 10

[Ethan Glasser-Camp (:glasserc)]

OK, so it never stops being an object. However, sometimes I was able to load an extension "too early" in the startup process, which meant it broke, which meant it didn't sync. So that's what that is about.

It looks like my UUID generation code doesn't work, because it assumes that returned UUIDs are strings (apparently they are nsIDs). It never occurred to me that UUIDs would not be strings, so I didn't even check for this in my tests (which even hardcode strings).

Here is a fix for the bug that should prevent broken keyrings from being generated in the future. However, anyone affected by this bug will have a broken keyring on the dev server as well. Do you think it's worth writing code to try to handle that on the client, or should we just wipe the dev server, or what?

Comment 11

[Andy McKay]

Feel free to wipe the dev server, I think we've set expectations correctly on this for the moment.

Comment 12

[Andy McKay]

Oh but once this landed and the dev server wiped, maybe just drop a note to dev-addons explaining why.

Comment 13

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

Comment on attachment 8815410 [details]
Bug 1319742 - UUIDs should be strings, not objects,

https://reviewboard.mozilla.org/r/96322/#review96604

::: toolkit/components/extensions/test/xpcshell/test_ext_storage_sync.js:408
(Diff revision 2)
>  };
>  const defaultCollectionId = extensionIdToCollectionId(loggedInUser, defaultExtensionId);
>  
>  function uuid() {
>    const uuidgen = Cc["@mozilla.org/uuid-generator;1"].getService(Ci.nsIUUIDGenerator);
> -  return uuidgen.generateUUID();
> +  return uuidgen.generateUUID().toString();

While this change looks fine, I'm interested to know why your tests didn't pick this up? ie, it seems like the test was using nsID objects, so should have fallen victim to the underlying bug.

IOW, istm that some additional test that failed before the patch but works afterwards would be valuable.

Comment 14

[Ethan Glasser-Camp (:glasserc)]

Comment on attachment 8815410 [details]
Bug 1319742 - UUIDs should be strings, not objects,

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

Comment 15

[Ethan Glasser-Camp (:glasserc)]

Per :markh's comments, here is a test that goes into an infinite loop without the toString() call. With the toString() call, it passes, although it seems to be illustrating yet another bug in the kinto.js library. Because this needs to be uplifted and it seemed urgent, I decided not to investigate or address the kinto.js issue, nor the increasing ugliness of the ext_storage_sync test suite, figuring that both of these can be addressed later.

Comment 16

[Ethan Glasser-Camp (:glasserc)]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=049c69f51070

Comment 17

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

Comment on attachment 8815410 [details]
Bug 1319742 - UUIDs should be strings, not objects,

https://reviewboard.mozilla.org/r/96322/#review96912

Thanks. Can you please open 2 additional bugs - one for the better time mocking (or however you would describe it) and add a reference to that bug in your test comments, and also the other bug you believe you found in kinto.js

Comment 18

[Ethan Glasser-Camp (:glasserc)]

Comment on attachment 8815410 [details]
Bug 1319742 - UUIDs should be strings, not objects,

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

Comment 19

[Ethan Glasser-Camp (:glasserc)]

I have created bug 1321570 and bug 1321571. I believe this can land now.

Comment 20

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/aa1833690db2
UUIDs should be strings, not objects, r=markh

Comment 21

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/aa1833690db2

Comment 22

[Ethan Glasser-Camp (:glasserc)]

Comment on attachment 8815410 [details]
Bug 1319742 - UUIDs should be strings, not objects,

Approval Request Comment
[Feature/Bug causing the regression]: 1253740
[User impact if declined]: addon developers will find it harder to begin testing this API 
[Is this code covered by automated tests?]: yes, a test is added as part of this patch
[Has the fix been verified in Nightly?]: not yet; I'm needinfo'ing the reporter
[Needs manual test from QE? If yes, steps to reproduce]: 
[List of other uplifts needed for the feature/fix]: none yet
[Is the change risky?]: no
[Why is the change risky/not risky?]: the entire feature is currently pref'd off by default
[String changes made/needed]: none

Comment 23

[Vasilica Tamas, QA [:vtamas]]

Attachment: error-sync.zip

I was still able to reproduce this issue using an old Fxa account on Firefox 53.0a1 (2016-12-04) under Windows 10 64-bit. See attached sync error logs.


The sync is completed but the data is not imported while using a new Fxa account on Firefox 53.0a1 (2016-12-04); success logs from about:sync-log:
 - http://pastebin.com/gyKmE0US
 - http://pastebin.com/QiqMYxr2
 - http://pastebin.com/BH8d5aM5
 - http://pastebin.com/aBpwi7Za

Comment 24

[Julien Cristau [:jcristau]]

Ethan, from comment 23 it sounds like there's still an issue with this on nightly?

Comment 25

[Ethan Glasser-Camp (:glasserc)]

Sorry for the delayed response. After studying comment 23, I think this is the behavior that I expected. Specifically:

- Old accounts will continue to fail to sync forever, because the data on the server is bad. This patch only fixes the client bug. In order to "fix" the affected accounts, I will have to wipe the server, which I didn't want to do until this change was uplifted (since it can just reproduce itself).

- New accounts will sync successfully. When webextensions are installed without an ID, they each get their own ID, so they don't share data, so when :vasilica_mihasca reports that data is not imported, that seems correct. The fact that the sync finished successfully means that the patch worked.

So I think I would still like this uplifted.

Comment 26

[Vasilica Tamas, QA [:vtamas]]

(In reply to Ethan Glasser-Camp (:glasserc) from comment #25)
 
> - Old accounts will continue to fail to sync forever, because the data on
> the server is bad. This patch only fixes the client bug. In order to "fix"
> the affected accounts, I will have to wipe the server, which I didn't want
> to do until this change was uplifted (since it can just reproduce itself).

Seems that the old accounts is a different scenario and needs a separate approach. Is there any logged bug or should I file a new issue? 

> - New accounts will sync successfully. When webextensions are installed
> without an ID, they each get their own ID, so they don't share data, so when
> :vasilica_mihasca reports that data is not imported, that seems correct. The
> fact that the sync finished successfully means that the patch worked.

So, from what I understand, those webextensions without ID will never be able to share data between profiles. Is this correct? Or are there any plans to implement this in the near future? 

Based on my testing and Ethan’s confirmation I am marking this issue as Verified.

Comment 27

[Ethan Glasser-Camp (:glasserc)]

You're totally right :vasilica_mihasca. I have opened bug 1323240 to track wiping the dev server. After some vigorous discussion in #webextensions about addons with temporary IDs, I have opened bug 1323228 and bug 1323225 to try to help clarify these points.

Comment 28

[Julien Cristau [:jcristau]]

Comment on attachment 8815410 [details]
Bug 1319742 - UUIDs should be strings, not objects,

Fix issues with webextensions without id in aurora52.

Thanks for double checking the verification results, Ethan!

Comment 29

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/f010f7b2006e

Comment 30

[Vasilica Tamas, QA [:vtamas]]

Confirm that this issue is also fixed on Firefox 52.0a2 (2016-12-27) under Windows 10 64-bit and Ubuntu 16.04 32-bit. The sync icon stops from spinning while synchronizing a webextension without id using a new Firefox account.

Comment 31

[Will Bamberg [:wbamberg]]

I think this is fixed by bug 1323225, so I'm marking this as dev-doc-complete. But let me know if you think anything else is needed.