994057 - Call to TPS.Sync() can result in two sync operations

Status: RESOLVED WORKSFORME

(Testing Graveyard :: TPS, defect)

Description

[Henrik Skupin [:whimboo][⌚️UTC+2] (away 10/03 - 10/13)]

If a test contains a [Sync] action, which gets executed after start-up of Firefox, another sync operation could happen right after. Most likely that one gets started due to the login process by Firefox itself. So we overlap here.

CROSSWEAVE INFO: ----------event observed: weave:service:sync:start
CROSSWEAVE INFO: ----------event observed: weave:service:sync:finish
CROSSWEAVE INFO: ----------event observed: weave:service:sync:start
CROSSWEAVE INFO: ----------event observed: weave:service:sync:finish

Thankfully our call comes first, so we are not affected by a race-condition for bug 992198.

Comment 1

[Cosmin Malutan, [:cosmin-malutan]]

Attachment: consoleText.txt

This fails often on production. 
Just right after our triggered sync call ends the periodical one starts. 
What I can say here is the by the time the browser opens for the first time with a profile in a test the preferences to delay the sync are the default ones.
https://github.com/mozilla/gecko-dev/blob/RELEASE_BASE_20140602/services/sync/tps/extensions/tps/resource/tps.jsm#L245

>CROSSWEAVE TEST PASS: executing action VERIFY on formdata
>CROSSWEAVE INFO: starting action: TPS__Sync
>CROSSWEAVE INFO: Executing Sync
>CROSSWEAVE INFO: ----------event observed: weave:service:sync:start
>CROSSWEAVE INFO: ----------event observed: weave:service:sync:finish
>CROSSWEAVE INFO: ----------event observed: weave:service:sync:start
>CROSSWEAVE ERROR: [phase3] Automatic sync got triggered, which is not allowed.
>CROSSWEAVE INFO: ----------event observed: quit-application-requested
>CROSSWEAVE INFO: Wiping data from server.
>1409832850135	Sync.BrowserIDManager	ERROR	Failed to fetch a token for authentication: [Exception... "App. Quitting"  nsresult: "0x80004004 (NS_ERROR_ABORT)"  location: "JS frame :: resource://services-common/async.js :: checkAppReady/onQuitApplication/Async.checkAppReady :: line 126"  data: no]
> 
>TEST-UNEXPECTED-FAIL | test_privbrw_formdata.js | [phase3] Automatic sync got triggered, which is not allowed.

Richard do you know in which circumstances the automatic sync won't be delayed, or when the browser checks for those preferences?

Comment 2

[Richard Newman [:rnewman]]

If an event occurs which will prompt a sync -- e.g., the regular timer fires -- it'll queue a sync on the next tick. If your code isn't yielding, the next sync will happen as soon as this one finishes, because it won't interleave and see that one is in process.

This is an artifact of TPS doing what it does: shoving its arms in up to the elbow and prodding at the innards of a spinning machine.

Automatic syncs will happen whenever Sync checks (which is often) and finds that it hasn't synced in a while. The only real 'delay' mechanism is backoff.

Comment 3

[Henrik Skupin [:whimboo][⌚️UTC+2] (away 10/03 - 10/13)]

So which option would we have then to fix that? Looks like this is the last remaining problem we have for the new Jenkins CI. I have no idea what those failures don't come up with an pre-existent FxA account, but only if we create it dynamically. Is there some specific state involved?

Comment 4

[Henrik Skupin [:whimboo][⌚️UTC+2] (away 10/03 - 10/13)]

Looks like this is always happening after restarting Firefox:

00:07:26 CROSSWEAVE INFO: ----------event observed: quit-application-requested
00:07:27 
00:07:27 (process:26851): GLib-CRITICAL **: g_slice_set_config: assertion 'sys_page_size == 0' failed
00:07:30 System JS : WARNING resource://tps/modules/bookmarks.jsm:38 - mutating the [[Prototype]] of an object will cause your code to run very slowly; instead create the object with the correct initial [[Prototype]] value using Object.create
00:07:30 CROSSWEAVE INFO: Sync version: 1.35.0
00:07:30 CROSSWEAVE INFO: Firefox buildid: 20141023194920
00:07:30 CROSSWEAVE INFO: Firefox version: 33.0.1
00:07:30 CROSSWEAVE INFO: Firefox Accounts enabled: true
00:07:30 CROSSWEAVE INFO: ----------event observed: weave:engine:start-tracking
00:07:30 CROSSWEAVE INFO: Waiting for weave:service:ready...
00:07:30 CROSSWEAVE INFO: weave:service:ready observed!
00:07:31 CROSSWEAVE INFO: Starting phase 3/4
00:07:31 CROSSWEAVE INFO: setting client.name to profile1
00:07:33 CROSSWEAVE INFO: ----------event observed: sessionstore-windows-restored
00:07:33 CROSSWEAVE INFO: starting action: TPS__Sync
00:07:33 CROSSWEAVE INFO: Executing Sync
00:07:39 CROSSWEAVE INFO: ----------event observed: weave:service:sync:start
00:07:39 CROSSWEAVE ERROR: [phase3] Automatic sync got triggered, which is not allowed.

Comment 5

[Richard Newman [:rnewman]]

whimboo: is this still something you'd like me to investigate? I'm very short on time right now, so I'm unlikely to have cycles until the middle of 37.

Comment 6

[Henrik Skupin [:whimboo][⌚️UTC+2] (away 10/03 - 10/13)]

Probably not right now. Given that we only see those failures with Firefox user accounts with a huge user id, I feel it is similar to the problem with signIn() as reported in bug 1066493. So we are eagerly waiting for bug 1057892 to be deployed to production. Once this is done, we can re-evaluate this bug.

CC'ing Ryan for letting him know about this additional problem, which might be related to the backend storage somehow.

Comment 7

[Henrik Skupin [:whimboo][⌚️UTC+2] (away 10/03 - 10/13)]

Looks like this problem is still present also with the signIn() failure gone.