1351678 - Sync error after logging using an existing account on a profile with already stored data

Status: VERIFIED FIXED

(WebExtensions :: Untriaged, defect, P3)

Description

[Vasilica Tamas, QA [:vtamas]]

Attachment: favourite_colour-1.0-fx.xpi

[Affected versions]:
Firefox 55.0a1 (2017-03-26)
Firefox 54.0a2 (2017-03-26)
Firefox 53.0b7 (20170327081421)


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

[Steps to reproduce]:
1.Launch Firefox with a clean profile and set up the configuration.
2.Install the attached webextenion.
3.Set a favourite colour in about:addons and click “Save” button.
4.Go to about:preferences#sync and login using an already used account.
5.Force a sync.

[Expected Results]:
Local data is kept and there are no errors encountered.

[Actual Results]:
- Local data is successfully kept but the following errors are thrown after the sync in completed: 
Warning: setting the doctor.lastRepairAdvance pref to the non-integer number 1490795925.77 converted it to the integer number 1490795925; to retain fractional precision, store non-integer numbers as strings.  Preferences.jsm:134
Sync encountered an error - see about:sync-log for the log file.  policies.js:731

[Additional notes]:
- Also at step 3, other errors appear in Browser Console:
TypeError: this._recipeManager is null[Learn More]  LoginManagerParent.jsm:73:9
Cannot send function call result: other side closed connection (call data: ({path:"storage.sync.set", args:[{colour:"3333333311111111"}]}))

Comment 1

[Vasilica Tamas, QA [:vtamas]]

Attachment: sync-error.txt

I am attaching the sync-log file

Comment 2

[Ethan Glasser-Camp (:glasserc)]

Yeah, I definitely didn't consider this something we would handle. After all, we already show a dialog indicating that two people's data could get scrambled together when the second login happens. I think the correct way to handle it is to flush the local DB after the user clicks "yes" on that dialog, or maybe just reset sync status.

Comment 3

[Vasilica Tamas, QA [:vtamas]]

(In reply to Ethan Glasser-Camp (:glasserc) from comment #2)
> Yeah, I definitely didn't consider this something we would handle. After
> all, we already show a dialog indicating that two people's data could get
> scrambled together when the second login happens. I think the correct way to
> handle it is to flush the local DB after the user clicks "yes" on that
> dialog, or maybe just reset sync status.

I think you misunderstood this scenario. There are no 2 logins, only one and therefore no “Merge Warning” dialog is displayed.

Comment 4

[Ethan Glasser-Camp (:glasserc)]

You're right, I misunderstood this scenario. Sorry for taking so long to get back to this. I'll try to have a patch together today.

Comment 5

[Ethan Glasser-Camp (:glasserc)]

Attachment: Bug 1351678: Handle resolved conflicts correctly,

The elements of the SyncResultObject#conflicts field are {local,
remote} pairs.  However, the elements of the SyncResultObject#resolved
field are just the resolutions, and trying to access "local" and
"remote" fields of those resolutions causes a crash. Add a test that
demonstrates the error, and then fix it.

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

Comment 6

[Kris Maglione [:kmag]]

Comment on attachment 8860118 [details]
Bug 1351678: Handle resolved conflicts correctly,

https://reviewboard.mozilla.org/r/132136/#review135488

::: toolkit/components/extensions/test/xpcshell/test_ext_storage_sync.js:1151
(Diff revision 1)
> +      yield extensionStorageSync.syncAll();
> +      const remoteValue = (yield extensionStorageSync.get(extension, "remote-key", context))["remote-key"];
> +      equal(remoteValue, 8,
> +            "locally set value overrides remote value");
> +
> +      dump(`wtf ${JSON.stringify(calls)}\n`);

Probably want to remove this.

Comment 7

[Ethan Glasser-Camp (:glasserc)]

Comment on attachment 8860118 [details]
Bug 1351678: Handle resolved conflicts correctly,

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

Comment 8

[Ethan Glasser-Camp (:glasserc)]

Comment on attachment 8860118 [details]
Bug 1351678: Handle resolved conflicts correctly,

https://reviewboard.mozilla.org/r/132136/#review135488

> Probably want to remove this.

Haha, oops! Sorry about that. I wish there was an eslint check for dump()..

Comment 9

[Ethan Glasser-Camp (:glasserc)]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=2508975134c0

Comment 10

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/5053fcd89b01
Handle resolved conflicts correctly, r=kmag

Comment 11

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

https://hg.mozilla.org/mozilla-central/rev/5053fcd89b01

Comment 12

[Vasilica Tamas, QA [:vtamas]]

Attachment: sync-logs.zip

I am still receiving the error-sync accompanied by a success-sync file on Firefox 55.0a1 (2017-05-01) under Windows 10 64-bit and Ubuntu 16.04 32-bit.

Any thoughts about this?

Comment 13

[Ethan Glasser-Camp (:glasserc)]

Sorry, I don't know anything about this failed sync. It appears to have something to do with Firefox Accounts information? The Extension-Storage part of the code doesn't appear to log any errors at all.

Comment 14

[Liz Henry (:lizzard) (privacy/fingerprinting team)]

Vasilica, are you still seeing errors?  Maybe you can file a new bug. 

Ethan, looks like 54 is also affected. If you can help us verify this fix it might be good to uplift to beta 54.

Comment 15

[Liz Henry (:lizzard) (privacy/fingerprinting team)]

Shane, do you still work on Fx Accounts? Can you help find someone who might know how to help here?

Comment 16

[Vasilica Tamas, QA [:vtamas]]

(In reply to Liz Henry (:lizzard) (needinfo? me) from comment #14)
> Vasilica, are you still seeing errors?  Maybe you can file a new bug. 

Checked again on Firefox 55.0a1 (2017-05-24) under Windows 10 64-bit and Ubuntu 16.04 32-bit and the sync was performed without errors. 
 
The following sync-error still appears on Firefox 54.0b10 (20170522172523) under both platforms: https://pastebin.com/qWx2hEYf

Comment 17

[Shane Tomlinson [:stomlinson]]

Hi :lizzard, 

I had a look at the referenced log and nothing looks particularly out of the ordinary from an FxA request P.O.V., but I have to admit I'm a bit out of my depth when it comes to knowing what the browser does.

My guess is that Mark Hammond would be able to direct you to the correct person/people, he works extensively with Sync. Shifting the ?ni to him.

Comment 18

[Ethan Glasser-Camp (:glasserc)]

Comment on attachment 8860118 [details]
Bug 1351678: Handle resolved conflicts correctly,

Approval Request Comment
[Feature/Bug causing the regression]: chrome.storage.sync
[User impact if declined]: Syncing of chrome.storage.sync keyrings may fail for users with multiple devices. This won't cause any real data loss but is annoying.
[Is this code covered by automated tests?]: Yes.
[Has the fix been verified in Nightly?]: Yes.
[Needs manual test from QE? If yes, steps to reproduce]: No.
[List of other uplifts needed for the feature/fix]: None.
[Is the change risky?]: Not really.
[Why is the change risky/not risky?]: It's a targeted fix for a function that doesn't seem to be being used by extensions "in the wild".
[String changes made/needed]: None.

Comment 19

[Gerry Chang [:gchang]]

Comment on attachment 8860118 [details]
Bug 1351678: Handle resolved conflicts correctly,

Fix a sync error with multiple devices and was verified. Beta54+. Should be in 54 beta 12.

Comment 20

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

(In reply to Vasilica Mihasca, QA [:vasilica_mihasca] from comment #16)
> The following sync-error still appears on Firefox 54.0b10 (20170522172523)
> under both platforms: https://pastebin.com/qWx2hEYf

The sync error log is due to the following entries:

> 1495700549267   Sync.Status DEBUG   Status for engine extension-storage: error.engine.reason.unknown_fail
> 1495700549267   Sync.Status DEBUG   Status.service: success.status_ok => error.sync.failed_partial
> 1495700549267   Sync.ErrorHandler   DEBUG   extension-storage failed: TypeError: conflict.remote is undefined (resource://gre/modules/ExtensionStorageSync.jsm:839:7) JS Stack trace: [e-mail]:839:7 < [e-mail]:98:7 < makeSpinningCallback/[e-mail]:168:27 < [e-mail]:234:12 < [e-mail]:44:12 < [e-mail]:164:21 < [e-mail]:720:5 < [e-mail]:222:7 < [e-mail]:169:15 < [e-mail]:1115:7 < [e-mail]:164:21 < [e-mail]:120:16 < [e-mail]:1105:12 < sync/<@service.js:1097:7 < [e-mail]:95:16 < [e-mail]:1086:5
> 1495700549269   Sync.Telemetry  TRACE   observed weave:engine:sync:error extension-storage

Ethan, can you confirm you patch should resolve this, or do we need a new bug?

Comment 21

[Ethan Glasser-Camp (:glasserc)]

Yes, this patch should resolve `conflict.remote is undefined`.

One of the logs Vasilica posted has an error starting like this:

> 1493715671035	FirefoxAccounts	ERROR	json parse error on response: [{"id":"01289872d160109697f095bbc447544e","lastAccessTime":null,"name":"vasilica.mihasca’s Nightly on P6079","type":"desktop","pushCallback":"https://updates.push.services.mozilla.com/wpush/v1/gAAAAABY_e8Kkl6arMesMx6PuGQ_jeoLrD-vNFMzEJSpviE1X7N7yO7I5-_D62Ma-DHwdt-7wXiCXxVBMXHXDWc2U1yWIQ5KKxZHrn7iFxk2VpzNNUURTdEEvo-LreHFLMvdQG5IprKt"...

This is the error I don't know anything about and should probably be in a new bug.

Comment 22

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-beta/rev/83e94c015805

Comment 23

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

(In reply to Ethan Glasser-Camp (:glasserc) from comment #21)
> > 1493715671035	FirefoxAccounts	ERROR	json parse error on response: [{"id":"01289872d160109697f095bbc447544e","lastAccessTime":null,"name":"vasilica.mihasca’s Nightly on P6079","type":"desktop","pushCallback":"https://updates.push.services.mozilla.com/wpush/v1/gAAAAABY_e8Kkl6arMesMx6PuGQ_jeoLrD-vNFMzEJSpviE1X7N7yO7I5-_D62Ma-DHwdt-7wXiCXxVBMXHXDWc2U1yWIQ5KKxZHrn7iFxk2VpzNNUURTdEEvo-LreHFLMvdQG5IprKt"...
> 
> This is the error I don't know anything about and should probably be in a
> new bug.

Ah, I missed that - that is bug 1362099, already fixed.

Comment 24

[Andrei Vaida [:avaida]]

(In reply to Ethan Glasser-Camp (:glasserc) from comment #18)
> [Is this code covered by automated tests?]: Yes.
> [Has the fix been verified in Nightly?]: Yes.
> [Needs manual test from QE? If yes, steps to reproduce]: No.

Setting qe-verify- based on Ethan's assessment on manual testing needs and the fact that this fix has automated coverage.