Sync hangs in form history sync if browser.formfill.enable is false, but history sync is enabled

RESOLVED FIXED in Firefox 29

Status

Cloud Services
Firefox Sync: Backend
RESOLVED FIXED
4 years ago
4 years ago

People

(Reporter: Roman Barczynski, Assigned: markh)

Tracking

({regression})

unspecified
mozilla30
regression
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox25 wontfix, firefox26 wontfix, firefox27 wontfix, firefox28 wontfix, firefox29 fixed, firefox30 fixed)

Details

(Whiteboard: [qa+][sync:rigor][sync:scale])

Attachments

(8 attachments, 3 obsolete attachments)

(Reporter)

Description

4 years ago
Created attachment 824606 [details]
first error log

User Agent: Mozilla/5.0 (X11; Linux x86_64; rv:24.0) Gecko/20100101 Firefox/24.0 (Beta/Release)
Build ID: 20130917081302

Steps to reproduce:

Firefox was not syncing correctly so I've decided to do clean run:
1. created new profile on my PC,
2. synced data to this profile,
3. resetted recovery key to clean everything from server side

after this synced started working, for about hour tabs were syncing every 5-10 minutes...

then I've paired my android phone, phone was synced correctly


Actual results:

After pairing phone sync icon on PC started spinning constantly for 10 minutes and error-...txt started appearing in weave/logs/ directory.

Hour later lastSync is still stucked on date before phone was paired, several error logs were added.


Expected results:

After pairing phone Sync on PC should still be able to sync data...
(Reporter)

Comment 1

4 years ago
Created attachment 824607 [details]
last success log (before errors)
(Reporter)

Comment 2

4 years ago
Maybe I should add it was Android Phone, with Firefox 25 installed (fresh install, all app data has been removed)
(Reporter)

Comment 3

4 years ago
I've managed to reproduce issue:
1. Reset recovery key to get rid of all server data,
2. Resync PC Firefox, you're now syncing one device,
3. Uninstall Android Firefox to clean all data & sync accounts from Android Firefox then install it again,
4. Pair Android Firefox to your PC Firefox, wait for sync,

5. At this point both devices sync correctly, no errors, tabs & bookmarks are synced for sure,

6. on Android Firefox install extension, in my case it was "YouTube Embed2Link",
7. Force sync on Android Firefox (from Android accounts settings),

8. After syncing Android Firefox with extension installed PC Firefox fails to sync in 100% cases.

I've done this 5 times, each time results are the same, resulting in PC Firefox fail sync.
(Reporter)

Comment 4

4 years ago
I've created new, empty sync account and I cannot reproduce this issue there so it seems to be related to my PC data (or amount of that data maybe?)
(Reporter)

Comment 5

4 years ago
When I disabled history sync (5000 items) issue does not occur, that is you can install anything you need on android firefox and sync still works.
Then:
1. Re-enable history sync, sync PC
2. Force sync on Android,
3. PC sync doesn't work again.
(Reporter)

Comment 6

4 years ago
Created attachment 825530 [details]
success log after re-enabling history syncing
(Reporter)

Comment 7

4 years ago
Created attachment 825538 [details]
error on PC after enabling history sync and syncing on android
The logs from the last Sync, on the load balancer, all look good except the following entry (IP address removed): 
A.B.C.D - - [31/Oct/2013:14:31:36 -0700] "  " - 0 "-" "-" "-" "ssl: -" node_s:- req_s:5.796677 retries:0 req_b:0 "c_l:-"

Note the retries field indicates 0.  This indicates that the LB isn't retrying the connection, and therefore the timeout is on the client side.
(Reporter)

Comment 9

4 years ago
Created attachment 825558 [details]
error with Trace enabled for resources, history & forms
That log suggests that

    Svc.FormHistory.update(changes, callbacks);

is never calling the provided callback.

That might well be because Bug 878677 never added handleError to that set of callbacks…
Status: UNCONFIRMED → NEW
Component: General → Firefox Sync: Backend
Ever confirmed: true
status-firefox25: --- → affected
status-firefox26: --- → affected
status-firefox27: --- → affected
status-firefox28: --- → affected
Depends on: 878677
Keywords: regression
Created attachment 825582 [details] [diff] [review]
Proposed patch. v1
Assignee: nobody → rnewman
Status: NEW → ASSIGNED
Attachment #825582 - Flags: review?(mhammond)
Whiteboard: [qa+]
Try build for testing: https://tbpl.mozilla.org/?tree=Try&rev=c607da715658
Build:

http://ftp.mozilla.org/pub/mozilla.org/firefox/try-builds/rnewman@mozilla.com-c607da715658/try-linux64/
(Reporter)

Comment 14

4 years ago
Created attachment 825785 [details]
error log for c607da715658 build

there are still some errors, icon keeps spinning indefinitely
(Assignee)

Comment 15

4 years ago
Comment on attachment 825582 [details] [diff] [review]
Proposed patch. v1

Review of attachment 825582 [details] [diff] [review]:
-----------------------------------------------------------------

Deferring review as I'm guessing from comment 14 it doesn't work as expected.

::: services/sync/modules/engines/forms.js
@@ +49,5 @@
>          cb(null, results);
> +      },
> +
> +      handleError: function (error) {
> +        cb(error);

If I read http://mxr.mozilla.org/mozilla-central/source/storage/src/mozStorageAsyncStatementExecution.cpp correctly, it seems handleCompletion will still be called after handleError(), so this might cause the callback to be called multiple times?

(I hope that's correct; https://developer.mozilla.org/en-US/docs/MozIStorageStatementCallback was vague about that, so I updated it to reflect my understanding above.  I'll need to fix that if I'm wrong)
I was reading FormHistory.jsm; you're right that in most cases the callbacks are passed to a statement, and so handleCompletion would be called.

Reading deeper, though:

http://dxr.mozilla.org/mozilla-central/source/toolkit/components/satchel/FormHistory.jsm#l939

To me, this looks like if one of the update-searches never completes (or something weird happens with tracking failure), we'll never call back into Sync.

(It also looks like if an error callback throws, searchFailed won't be set. Don't know if that's relevant.)

Is that a possibility? Is there anything else in FormHistory.update that would result in a callback never being issued?
Flags: needinfo?(mhammond)
(Assignee)

Comment 17

4 years ago
(In reply to Richard Newman [:rnewman] from comment #16)
> http://dxr.mozilla.org/mozilla-central/source/toolkit/components/satchel/
> FormHistory.jsm#l939
> 
> To me, this looks like if one of the update-searches never completes (or
> something weird happens with tracking failure), we'll never call back into
> Sync.

I'm not sure what we could do about the "never completes" case - but it's certainly true we rely on that.

However, the block at l939 looks OK to me - it looks like the callback will be called if all statements complete.

> (It also looks like if an error callback throws, searchFailed won't be set.
> Don't know if that's relevant.)
> 
> Is that a possibility? Is there anything else in FormHistory.update that
> would result in a callback never being issued?

The only other case I can see that might be problematic is when the update() method throws an exception - either directly, or via validateSearchData() etc.  It's not immediately clear to me that such exceptions would end up in the sync log.  I'd guess they might end up in the console, but even that isn't clear, and even if it was, it's not clear that has been checked in this error case.

I'm not that familiar with sync - which part of the most recent log tells you that update() was called but the callback never issued?
Unassigning bugs that I'm not actively working on.
Assignee: rnewman → nobody
Summary: Sync stuck, icon keeps spinning, data is not synced to cloud. → Sync hangs in form history sync
Whiteboard: [qa+] → [qa+][sync:rigor][sync:scale]
This still seems to be affecting users.

https://support.mozilla.org/en-US/questions/986057#answer-534173

Mark, Gavin, do you have any ideas?
Flags: needinfo?(gavin.sharp)
(Assignee)

Comment 20

4 years ago
A shot in the dark here, but I can reproduce this if the pref browser.formfill.enable is set to false - no callback is made in that case as we attempt to save the incoming form data.  Is it possible you have (or had) this pref set to false?

Either way, I guess this is something we should fix.  The enabled state of FormHistory isn't exposed other than via that pref, so we could either (a) check that pref, (b) have the update() method return a bool, with false indicating it is disabled and thus no callback can be expected, or (c) having update() make a callback anyway in this case (but I'm not sure what sane data it could pass to reflect this)
Flags: needinfo?(mhammond) → needinfo?(romke)
(Reporter)

Comment 21

4 years ago
I have browser.formfill.enable set to false.
Setting it to true results in successful sync, but in my case I still would want to sync history without storing form history.
Flags: needinfo?(romke)
Good sleuthing, Mark!

Roman: "history" in Sync encompasses both form history and browsing history. That Sync is hanging when form history is disabled is just a bug, and now we know the cause we can fix it.

Thanks for your help!
Summary: Sync hangs in form history sync → Sync hangs in form history sync if browser.formfill.enable is false, but history sync is enabled
(Assignee)

Comment 23

4 years ago
I'll take this.  A quick chat on fx-team indicated that the .update() method should call the handleError() callback with (a new) Ci.mozIStorageStatementCallback.REASON_DISABLED.

Then sync will supply the error callback and handle this case (by treating it as "normal")

Dolske, I'll be asking you for review of that change to FormHistory.jsm, so does that sound OK to you?
Assignee: nobody → mhammond
Flags: needinfo?(gavin.sharp)
Blocks: 905997
(Assignee)

Updated

4 years ago
Attachment #825582 - Attachment is obsolete: true
Attachment #825582 - Flags: review?(mhammond)
(Assignee)

Comment 24

4 years ago
Created attachment 8379330 [details] [diff] [review]
0001-Bug-932759-part-1-FormHistory.update-calls-handleErr.patch

This patch adds a new constant mozIStorageStatementCallback::REASON_DISABLED - note I didn't bump the uuid as new constants shouldn't need a bump and we are going to request uplift of this to Aurora and possibly even further.

It also updates FormHistory.update() to call handleError with this new reason code if browser.formfill.enable is false.
Attachment #8379330 - Flags: review?(dolske)
(Assignee)

Comment 25

4 years ago
Created attachment 8379333 [details] [diff] [review]
0002-Bug-932759-part-2-Have-form-sync-work-correctly-if-F.patch

Have form sync handle a REASON_DISABLED error.
Attachment #8379333 - Flags: review?(rnewman)
Comment on attachment 8379333 [details] [diff] [review]
0002-Bug-932759-part-2-Have-form-sync-work-correctly-if-F.patch

Review of attachment 8379333 [details] [diff] [review]:
-----------------------------------------------------------------

Can we get a trivial test for this?
Attachment #8379333 - Flags: review?(rnewman) → review+
Comment on attachment 8379330 [details] [diff] [review]
0001-Bug-932759-part-1-FormHistory.update-calls-handleErr.patch

Review of attachment 8379330 [details] [diff] [review]:
-----------------------------------------------------------------

::: storage/public/mozIStorageStatementCallback.idl
@@ +45,5 @@
>     */
>    const unsigned short REASON_FINISHED = 0;
>    const unsigned short REASON_CANCELED = 1;
>    const unsigned short REASON_ERROR = 2;
> +  const unsigned short REASON_DISABLED = 3;

I'm sorry but "disabled" is not a valid state for Storage, and more specifically for a statement, this should be handled differently by the consumer of the Storage API.

You can define your own error constants in FormHistory using the same values and add a disabled reason there.
Attachment #8379330 - Flags: review-
or you could just check .enabled in the handleError check
(Assignee)

Comment 29

4 years ago
Comment on attachment 8379330 [details] [diff] [review]
0001-Bug-932759-part-1-FormHistory.update-calls-handleErr.patch

Fair enough - thanks!
Attachment #8379330 - Flags: review?(dolske)
(Assignee)

Comment 30

4 years ago
(In reply to Marco Bonardo [:mak] from comment #28)
> or you could just check .enabled in the handleError check

Not sure what you mean here?  

In the meantime, going with the approach from the other patch - I could add a new REASON_DISABLED flag locally to FormHistory, but then I need to expose it to consumers.  I could add it on the FormHistory object, but that doesn't seem perfect (no const semantics, a getter?).  I could expose it as a top-level symbol - eg, FORMHISTORY_REASON_DISABLED?

Another alternative would be for .update() to return a bool which is cleaner in some ways - although I was steered in this direction on #fx-team.

Happy to take any approach with your advice though :)




, this version keeps the constant local - it uses -1, which seems somewhat appropriate.
Flags: needinfo?(mak77)
(In reply to Mark Hammond [:markh] from comment #30)
> (In reply to Marco Bonardo [:mak] from comment #28)
> > or you could just check .enabled in the handleError check
> 
> Not sure what you mean here?  

I mean that when a consumer gets handleError, he may check FormHistory.enabled to figure if that's the reason of the failure, if they care about the reason at all. So here you would just callback the error as usual.

> In the meantime, going with the approach from the other patch - I could add
> a new REASON_DISABLED flag locally to FormHistory, but then I need to expose
> it to consumers.

fwiw you may expose it as FormHistory.ERROR_REASON_DISABLED (and the same for the others)

> Another alternative would be for .update() to return a bool which is cleaner
> in some ways - although I was steered in this direction on #fx-team.

I think it's not worth doing this for a very simple reason, we may want to move this interface to promises in future, and then here we'd return a promise that would resolve to some more useful object
Flags: needinfo?(mak77)
(Assignee)

Comment 32

4 years ago
Created attachment 8380564 [details] [diff] [review]
0001-Bug-932759-part-1-Expose-FormHistory.enabled.-r-mak.patch

(In reply to Marco Bonardo [:mak] from comment #31)
> (In reply to Mark Hammond [:markh] from comment #30)
> > (In reply to Marco Bonardo [:mak] from comment #28)
> > > or you could just check .enabled in the handleError check
> > 
> > Not sure what you mean here?  
> 
> I mean that when a consumer gets handleError, he may check
> FormHistory.enabled to figure if that's the reason of the failure

But there's no such attribute :)  Adding it does seem like a good option.
Attachment #8379330 - Attachment is obsolete: true
Attachment #8380564 - Flags: review?(mak77)
(Assignee)

Comment 33

4 years ago
Created attachment 8380565 [details] [diff] [review]
0002-Bug-932759-part-2-Have-form-sync-work-correctly-if-F.patch

With a test and updated for the new part 1; carrying r=rnewman forward.
Attachment #8379333 - Attachment is obsolete: true
Attachment #8380565 - Flags: review+

Updated

4 years ago
Attachment #8380564 - Flags: review?(mak77) → review+
I still think we should notify handleError in update() if the service is disabled though you may file a follow-up for that (it would also require a test). Just returning without calling back sounds error-prone for the consumer.
(Assignee)

Comment 35

4 years ago
(In reply to Marco Bonardo [:mak] from comment #34)
> I still think we should notify handleError in update() if the service is
> disabled though you may file a follow-up for that (it would also require a
> test). Just returning without calling back sounds error-prone for the
> consumer.

Sure, I'll open a followup - but FTR, Sync has no error handler, so doing this would not have helped this specific use-case.  Calling handleCompletion *would* have caused us to do the right thing, and it could be argued this is a reasonable response (ie, the operation completed without actually doing anything)

Anyway, I'll open a new bug and reference these comments.
(Assignee)

Comment 36

4 years ago
Opened bug 976940 for the followup.

https://hg.mozilla.org/integration/fx-team/rev/0853b374d32a
https://hg.mozilla.org/integration/fx-team/rev/11b0efa84735
Thanks for tackling this, Mark, and thanks for your patience, Roman!

Let's bake this for a few days, verify, and then uplift as high as we can.
status-firefox29: --- → affected
status-firefox30: --- → fixed
Whiteboard: [qa+][sync:rigor][sync:scale] → [qa+][sync:rigor][sync:scale][needs uplift]
Target Milestone: --- → mozilla30
https://hg.mozilla.org/mozilla-central/rev/0853b374d32a
https://hg.mozilla.org/mozilla-central/rev/11b0efa84735
Status: ASSIGNED → RESOLVED
Last Resolved: 4 years ago
Resolution: --- → FIXED
(Assignee)

Comment 39

4 years ago
Comment on attachment 8380564 [details] [diff] [review]
0001-Bug-932759-part-1-Expose-FormHistory.enabled.-r-mak.patch

[Approval Request Comment]
Bug caused by (feature/regressing bug #): Unknown
User impact if declined: Users who have the pref browser.formfill.enable=False (either implicitly or via an addon etc) will have their sync hang and never complete.
Testing completed (on m-c, etc.): Landed on m-c
Risk to taking this patch (and alternatives if risky): Low risk
String or IDL/UUID changes made by this patch: None
Attachment #8380564 - Flags: approval-mozilla-aurora?
(Assignee)

Comment 40

4 years ago
Comment on attachment 8380565 [details] [diff] [review]
0002-Bug-932759-part-2-Have-form-sync-work-correctly-if-F.patch

[Approval Request Comment]
Bug caused by (feature/regressing bug #): Unknown
User impact if declined: Users who have the pref browser.formfill.enable=False (either implicitly or via an addon etc) will have their sync hang and never complete.
Testing completed (on m-c, etc.): Landed on m-c
Risk to taking this patch (and alternatives if risky): Low risk
String or IDL/UUID changes made by this patch: None
Attachment #8380565 - Flags: approval-mozilla-aurora?
Attachment #8380564 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
Attachment #8380565 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
status-firefox25: affected → wontfix
status-firefox26: affected → wontfix
status-firefox27: affected → wontfix
status-firefox28: affected → wontfix
https://hg.mozilla.org/releases/mozilla-aurora/rev/62881d64ba58
https://hg.mozilla.org/releases/mozilla-aurora/rev/fc613a7534ce
status-firefox29: affected → fixed
Whiteboard: [qa+][sync:rigor][sync:scale][needs uplift] → [qa+][sync:rigor][sync:scale]
Duplicate of this bug: 973483
Duplicate of this bug: 980518
You need to log in before you can comment on or make changes to this bug.