988035 - changing from unchecked to checked sync data type doesn't sync

Status: RESOLVED INVALID

(Firefox :: Sync, defect)

Description

[Edwin Wong [:edwong]]

Attachment: toggleDataType.txt

please wait 5-10 sec between each 'sync now' event
1. on profile A - create an FxAcct with 'choose what to sync' is checked.
2. enter user:pw, next, then verify acct by clicking link in email
3. when sync data types dialog displays, deselect 'bookmarks'
4. add some book marks and select tools > sync now
5. on profile B - sign in with acct from step 1
6. add some bookmarks and select tools > sync now
7. in profile A - sync now to confirm book marks don't sync
8. now go into prefs > sync > select 'book marks'
9. do sync now

actual: bookmarks are not synced in profile A form profile B.  See log

1395785268978	Sync.Engine.Bookmarks	DEBUG	Resetting bookmarks last sync time
1395785268978	Sync.Engine.Bookmarks	DEBUG	First sync, uploading all items
1395785268985	Sync.Store.Bookmarks	DEBUG	No node for GUID mobile; returning no children.
1395785268985	Sync.Engine.Bookmarks	INFO	14 outgoing items pre-reconciliation
1395785269001	Sync.Engine.Bookmarks	INFO	Records: 0 applied, 0 successfully, 0 failed to apply, 0 newly failed to apply, 0 reconciled.

toward the bottom i see this:
1395785270014	Sync.Service	DEBUG	Uploading meta/global: {"id":"global","modified":1395784844.82,"payload":"{\"syncID\":\"GfukZdHw1xe7\",\"storageVersion\":5,\"declined\":[\"bookmarks\"],

expected: they should be

Comment 1

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

CC rnewman.  It looks like re-selecting an engine doesn't remove the engine from 'declined'.

Comment 2

[Richard Newman [:rnewman]]

I tested this quite thoroughly, so that would be a surprise.

Comment 3

[Catalin Suciu [:csuciu]]

This is what happens on Ubuntu 12.04 and Nightly 31.0a1 (2014-03-26) when following the steps from comment #0:

After step 5: On profile B, bookmarks section gets deselected automatically when the initial sync starts, so I had to manually select it before continuing with adding bookmarks and sync.  

At step 7: On profile A, bookmarks section gets selected automatically when sync starts, and the bookmarks from profile B are synced into profile A 

The same thing happens when testing on other sections (e.g History)

Comment 4

[Edwin Wong [:edwong]]

karl can you try to rerpo this

Comment 5

[Karl Thiessen [:kthiessen, he/him]]

Any particular Nightly we're interested in, or will the one from last night do the trick?

Comment 6

[Edwin Wong [:edwong]]

lastest is bestest.  RE: to comment #3, I did in fact check the bookmark box and confirm upload of my bookmarks.  The log file attachment shows syncing but also a 'decline':['bookmarks'].

Comment 7

[Karl Thiessen [:kthiessen, he/him]]

Using latest Nightly, the problem I run into is getting the last Sync on profile A to actually run when I hit 'Sync Now' -- I don't get a success log or a failure log.  I'm not sure that the act of checking the 'Bookmarks' box in Sync Preferences actually sets the 'dirty, needs to be re-synced to server' flag.

Still investigating, more to come.

Comment 8

[Karl Thiessen [:kthiessen, he/him]]

(Begin slight digression.)

I never wanted to be the sort of QA person who drops f-bombs into bug reports.  But I would like it noted that the behaviour of the services.sync.log.appender.file.logOn* preferences, such that they reset themselves with every restart if you don't explicitly put them in a user.js or similar ... is not optimal.

If I change them, I want them to bloody well stay changed.  I will find the appropriate bug (as I am certain I am not the only one with this wish), and copy this comment into it wholesale.

(End slight digression.)

The above is why I couldn't find the success log, obviously.

Beginning a new testing cycle with the logging preferences (I hope) pinned to their appropriate values.

Comment 9

[Karl Thiessen [:kthiessen, he/him]]

Short result:  Once I re-checked the bookmarks checkbox and re-synced, the bookmarks do sync as expected as in comment #6.

As for the log showing 'bookmarks' still in 'decline' ...

One thing I have noticed, from my logs, after I re-check the 'bookmarks' box:

=== begin excerpt ===

1395857344603	Sync.Synchronizer	INFO	meta/global changed locally: reuploading.
1395857344603	Sync.Service	DEBUG	Uploading meta/global: {"payload":"{\"syncID\":\"3DJpJJBA47Q0\",\"storageVersion\":5,\"declined\":[\"prefs\",\"addons\",\"bookmarks\"],\"engines\":{\"clients\":{\"version\":1,\"syncID\":\"nwTvo6nGMpqq\"},\"forms\":{\"version\":1,\"syncID\":\"0033pOLK743_\"},\"history\":{\"version\":1,\"syncID\":\"5emNvvxRkVX5\"},\"passwords\":{\"version\":1,\"syncID\":\"GZ5VO_u81aTO\"},\"tabs\":{\"version\":1,\"syncID\":\"QrZrR6JGaw5Q\"},\"bookmarks\":{\"version\":2,\"syncID\":\"4MFmoWyAHj_d\"}}}","modified":1395854508.4,"id":"global"}
1395857344605	Sync.Resource	DEBUG	PUT Length: 501
1395857344639	Sync.Resource	DEBUG	mesg: PUT success 200 https://sync-6-us-west-2.sync.services.mozilla.com/1.5/108973/storage/meta/global
1395857344639	Sync.Resource	DEBUG	PUT success 200 https://sync-6-us-west-2.sync.services.mozilla.com/1.5/108973/storage/meta/global
1395857344640	Sync.Status	DEBUG	Status.sync: success.sync => success.sync
1395857344640	Sync.Status	DEBUG	Status.service: success.status_ok => success.status_ok
1395857344640	Sync.Synchronizer	INFO	Sync completed at 2014-03-26 11:09:04 after 0.33 secs.
1395857344641	Sync.Declined	DEBUG	Handling remote declined: ["prefs","addons","bookmarks"]
1395857344641	Sync.Declined	DEBUG	Handling local declined: ["prefs","addons"]
1395857344641	Sync.Declined	DEBUG	Declined changed? true
1395857344641	Sync.Service	DEBUG	Uploading meta/global: {"payload":"{\"syncID\":\"3DJpJJBA47Q0\",\"storageVersion\":5,\"declined\":[\"prefs\",\"addons\"],\"engines\":{\"clients\":{\"version\":1,\"syncID\":\"nwTvo6nGMpqq\"},\"forms\":{\"version\":1,\"syncID\":\"0033pOLK743_\"},\"history\":{\"version\":1,\"syncID\":\"5emNvvxRkVX5\"},\"passwords\":{\"version\":1,\"syncID\":\"GZ5VO_u81aTO\"},\"tabs\":{\"version\":1,\"syncID\":\"QrZrR6JGaw5Q\"},\"bookmarks\":{\"version\":2,\"syncID\":\"4MFmoWyAHj_d\"}}}","modified":1395854508.4,"id":"global"}
1395857344643	Sync.Resource	DEBUG	PUT Length: 487
1395857344677	Sync.Resource	DEBUG	mesg: PUT success 200 https://sync-6-us-west-2.sync.services.mozilla.com/1.5/108973/storage/meta/global
1395857344677	Sync.Resource	DEBUG	PUT success 200 https://sync-6-us-west-2.sync.services.mozilla.com/1.5/108973/storage/meta/global

=== end excerpt ===

It looks like the first of those meta/global JSON blobs is the before-state (perhaps the remote-state before the upload?) and the second one is the after-state (where local and remote are again in harmony).

The two DEBUG stanzas are labelled nearly identically, so it's very hard to tell them apart.  Perhaps this was the source of confusion about whether or not 'bookmarks' was actually in 'declined,' above?

Long-winded comment is long-winded.  Sorry for the verbosity.

Comment 10

[Richard Newman [:rnewman]]

Karl: would it be fair to summarize your comment as WORKSFORME?

A great tip for debugging this:

* Enable chrome debugging: devtools.chrome.enabled = true
* Launch Firefox.
* Very quickly, open the Browser Console (Cmd-Shift-J on Mac), click the dropdown next to Net, and choose "Log request and response bodies".
* Now every time there's a sync, you can click on the GET or PUT to meta/global and see what was exchanged. No log reading necessary.

That's what I did for verifying the declined work the first time around.

Comment 11

[Edwin Wong [:edwong]]

also note that your pref gets reset if you 'disconnect' the account.  It's a known issue.  You can restart if you have a user.js pref to overwrite it.

Comment 12

[Karl Thiessen [:kthiessen, he/him]]

(In reply to Richard Newman [:rnewman] from comment #10)

Yes, WORKSFORME, and thank you for the tip.  If I'd been thinking clearly, I would have used HttpFox or similar at the outset.

Comment 13

[Richard Newman [:rnewman]]

Edwin, back to you to decide whether to close out or do further investigation.

Comment 14

[Edwin Wong [:edwong]]

Hmm - either running it now or after i changed the name of my device (they were the same before) - it's working.  Sync just isn't very deterministic. I'll just close as invalid.

Comment 15

[Edwin Wong [:edwong]]

fwiw - i can repro the problem very easily if i
* profile A - uncheck bookmarks
* delete all in profile B, sync now
* profile A - sync now
* profile A - check bookmark
* profile A - sync now

this could be the delete all bookmarks bug that i'm hitting.  but this makes me sad.  I'll log a new bug.