Webextensions without id cause the sync icon to spin forever

VERIFIED FIXED in Firefox 52

Status

P1
normal
VERIFIED FIXED
2 years ago
9 months ago

People

(Reporter: vasilica.mihasca, Assigned: glasserc)

Tracking

({dev-doc-complete})

Trunk
mozilla53
dev-doc-complete
Dependency tree / graph

Firefox Tracking Flags

(firefox50 unaffected, firefox51 unaffected, firefox52 verified, firefox53 verified)

Details

(Whiteboard: [sync]triaged)

Attachments

(3 attachments)

[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.
Summary: Webextensions without id causes the sync icon to spin forever → Webextensions without id cause the sync icon to spin forever
(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)
Flags: needinfo?(vasilica.mihasca)

Comment 2

2 years ago
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.
Keywords: dev-doc-needed
(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
Flags: needinfo?(vasilica.mihasca)
Posted file sync-logs.zip
I’m attaching the accessible logs files.
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: waitForSyncCallback@async.js:98:7 < makeSpinningCallback/callback.wait@async.js:168:27 < promiseSpinningly@async.js:234:12 < ExtensionStorageEngine.prototype._sync@extension-storage.js:46:12 < WrappedNotify@util.js:166:21 < Engine.prototype.sync@engines.js:689:5 < _syncEngine@enginesync.js:321:7 < sync@enginesync.js:168:15 < onNotify@service.js:1328:7 < WrappedNotify@util.js:166:21 < WrappedLock@util.js:121:16 < _lockedSync@service.js:1318:12 < sync/<@service.js:1310:14 < WrappedCatch@util.js:95:16 < sync@service.js:1298:5
Flags: needinfo?(eglassercamp)

Updated

2 years ago
Assignee: nobody → eglassercamp
Priority: -- → P1
Whiteboard: [sync]triaged
(Assignee)

Comment 6

2 years ago
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.
(Assignee)

Comment 7

2 years ago
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 hidden (mozreview-request)
Comment hidden (mozreview-request)
(Assignee)

Comment 10

2 years ago
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?
Flags: needinfo?(eglassercamp) → needinfo?(amckay)

Comment 11

2 years ago
Feel free to wipe the dev server, I think we've set expectations correctly on this for the moment.
Flags: needinfo?(amckay)

Comment 12

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

Comment 13

2 years ago
mozreview-review
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 hidden (mozreview-request)
(Assignee)

Comment 15

2 years ago
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.
Flags: needinfo?(markh)

Comment 17

2 years ago
mozreview-review
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
Attachment #8815410 - Flags: review?(markh) → review+
Comment hidden (mozreview-request)
(Assignee)

Comment 19

2 years ago
I have created bug 1321570 and bug 1321571. I believe this can land now.
Flags: needinfo?(markh)
Keywords: checkin-needed

Comment 20

2 years ago
Pushed by ryanvm@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/aa1833690db2
UUIDs should be strings, not objects, r=markh
Keywords: checkin-needed

Comment 21

2 years ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/aa1833690db2
Status: NEW → RESOLVED
Last Resolved: 2 years ago
status-firefox53: affected → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla53
(Assignee)

Comment 22

2 years ago
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
Flags: needinfo?(vasilica.mihasca)
Attachment #8815410 - Flags: approval-mozilla-aurora?
Posted file 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
Flags: needinfo?(vasilica.mihasca)
Ethan, from comment 23 it sounds like there's still an issue with this on nightly?
Flags: needinfo?(eglassercamp)
(Assignee)

Comment 25

2 years ago
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.
Flags: needinfo?(eglassercamp)
(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.
Status: RESOLVED → VERIFIED
status-firefox53: fixed → verified
(Assignee)

Updated

2 years ago
See Also: → bug 1323228
(Assignee)

Updated

2 years ago
Blocks: 1323240
(Assignee)

Comment 27

2 years ago
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 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!
Attachment #8815410 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+

Comment 29

2 years ago
bugherderuplift
https://hg.mozilla.org/releases/mozilla-aurora/rev/f010f7b2006e
status-firefox52: affected → fixed
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.
status-firefox52: fixed → verified
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.
Keywords: dev-doc-needed → dev-doc-complete

Updated

9 months ago
Product: Toolkit → WebExtensions
You need to log in before you can comment on or make changes to this bug.