990509 - TPS test failure in test_tabs.js: "[phase3] Exception caught: ASSERTION FAILED! error locating tab"

Status: VERIFIED FIXED

(Firefox :: Sync, defect)

Description

[Andrei Eftimie]

Attachment: tps_test_tabs_log.txt

Attached is a full log.

test_tabs.js fails in phase3 with ASSERTION FAILED! error locating tab

Comment 1

[Henrik Skupin [:whimboo][⌚️UTC+2]]

It's not happening all the time so it might be something is still left over from a previous run which gets us in conflict. Or the test needs an update.

Comment 2

[Andrei Eftimie]

It doesn't look like this is influenced by previous runs / tests.

What I see is that we either don't wait for the UI to properly update (read: open the synced tabs) or we don't receive correct sync data.

Comment 3

[Henrik Skupin [:whimboo][⌚️UTC+2]]

You might want to run in --debug mode and check the trace output for the tabs engine.

Comment 4

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Andrei, can you give us the feedback? If not please let me know and I will take this bug. I don't want to wait longer to get it fixed.

Comment 5

[Henrik Skupin [:whimboo][⌚️UTC+2]]

This also fails for test_bug535326.js, test_privbrw_tabs.js, and test_special_tabs.js. Maybe all of those failures are related.

Comment 6

[Andrei Eftimie]

Attachment: tps_test_tabs_log2.txt

Attached is an updated log run with --debug

I'll try figuring this issue out today

Comment 7

[Andrei Eftimie]

Attachment: tps_test_tabs_log_PASS.txt

Interesting, this test is only failing intermittently now.
Here's a passing log with debug.

I'm comparing them atm to see where the difference is.

Comment 8

[Andrei Eftimie]

Attachment: log_PASS_cleaned.txt

Comment 9

[Andrei Eftimie]

Attachment: log_FAILED_cleaned.txt

Here are the 2 cleaned versions of the PASSING and FAILING log files.
By cleaned I mean that I removed leading timestamps and merged non-relevant parts such as timestamps, ids, encoded sent/received content.

A diff between these 2 files reveals what was different in each run.
I've also left the original logs attached. They might still be useful to somebody.

====

At a short glance there are differences in what has been synced, number of synced items. I'll make a short readable map on top of the actual test from these differences.

Comment 10

[Andrei Eftimie]

TL;DR:

The problem is in Phase2, we create the tabs, but when we sync, only 1 gets sent
(the one originally open) the 2 newly created tabs are not.

Here's more info:

PHASE1 is nearly identical.
---
In the FAILING test we update the score twice (its just a 1 digit increase).
That would mean the sync has a higher priority [1]. I don't see this affecting
the test. We Sync at the end of the phase.

PHASE2
---
1) [Sync], we get different items:
> Sync.Engine.Bookmarks TRACE Downloading & applying server changes

== Incoming ==

PASS:
> "type":"bookmark","title":"Help and Tutorials","parentName":"Mozilla Firefox","bmkUri":"https://www.mozilla.org/en-US/firefox/help/"
> Sync.Engine.Bookmarks TRACE Finding mapping: Mozilla Firefox, bhttps://www.mozilla.org/en-US/firefox/help/:Help and Tutorials
> Sync.Engine.Bookmarks TRACE Ignoring incoming item because the local item is identical.
> [..]
> "type":"bookmark","title":"About Us","parentName":"Mozilla Firefox","bmkUri":"https://www.mozilla.org/en-US/about/"
> Sync.Engine.Bookmarks TRACE Finding mapping: Mozilla Firefox, bhttps://www.mozilla.org/en-US/about/:About Us
> Sync.Engine.Bookmarks TRACE Ignoring incoming item because the local item is identical.
> [..]
> Sync.Engine.Bookmarks INFO  Records: 4 applied, 4 successfully, 0 failed to apply, 0 newly failed to apply, 8 reconciled.
> Sync.SyncScheduler  TRACE Handling weave:engine:sync:applied
> Sync.SyncScheduler  TRACE Engine bookmarks successfully applied 4 items.


FAIL:
> "type":"bookmark","title":"Help and Tutorials","parentName":"Mozilla Firefox","bmkUri":"https://www.mozilla.org/en-US/firefox/help/"
> Sync.Engine.Bookmarks TRACE Finding mapping: Mozilla Firefox, bhttps://www.mozilla.org/en-US/firefox/help/:Help and Tutorials
> Sync.Engine.Bookmarks WARN  DATA LOSS: Both local and remote changes to record: XCubz7bMpNM4
> Sync.Store.Bookmarks  TRACE Updating XCubz7bMpNM4 (8)
> Sync.Store.Bookmarks  TRACE Number of rows matching GUID XCubz7bMpNM4: 1
> [..]
> "type":"bookmark","title":"About Us","parentName":"Mozilla Firefox","bmkUri":"https://www.mozilla.org/en-US/about/"
> Sync.Engine.Bookmarks TRACE Finding mapping: Mozilla Firefox, bhttps://www.mozilla.org/en-US/about/:About Us
> Sync.Engine.Bookmarks WARN  DATA LOSS: Both local and remote changes to record: dRyRWT2QUJqj
> [..]
> Sync.Engine.Bookmarks INFO  Records: 6 applied, 6 successfully, 0 failed to apply, 0 newly failed to apply, 6 reconciled.
> Sync.SyncScheduler  TRACE Handling weave:engine:sync:applied
> Sync.SyncScheduler  TRACE Engine bookmarks successfully applied 6 items.

== Outgoing ==

PASS:
> Sync.Engine.Bookmarks TRACE Preparing 4 outgoing records
FAIL:
> Sync.Engine.Bookmarks TRACE Preparing 6 outgoing records
We have the 2 above mentioned items extra in the outgoing round.

2) [Tabs.verify, tabs1] // Same
3) [Tabs.add, tabs2] // Same

4) [Sync] Here we have another difference:

PASS:
> Sync.Store.Tabs TRACE Created tabs 3 of 3
> Sync.Store.Tabs TRACE Wrapping tab: {"title":"Bye","urlHistory":["data:text/html,<html><head><title>Bye</title></head><body>Bye</body></html>"],"icon":"","lastUsed":1396514741}
> Sync.Store.Tabs TRACE Wrapping tab: {"title":"Firefox Nightly First Run Page","urlHistory":["http://www.mozilla.org/en-US/firefox/nightly/firstrun/"],"icon":"","lastUsed":1396510259}
> Sync.Store.Tabs TRACE Wrapping tab: {"title":"Crossweave Test Page 3","urlHistory":["http://hg.mozilla.org/automation/crossweave/raw-file/2d9aca9585b6/pages/page3.html"],"icon":"","lastUsed":1396514740}
> Sync.Engine.Tabs  TRACE Outgoing: { id: VTxjM8Cm73AP  index: 0  modified: undefined  ttl: 604800  payload: {"id":"VTxjM8Cm73AP","clientName":"profile2","tabs":[{"title":"Bye","urlHistory":["data:text/html,<html><head><title>Bye</title></head><body>Bye</body></html>"],"icon":"","lastUsed":1396514741},{"title":"Firefox Nightly First Run Page","urlHistory":["http://www.mozilla.org/en-US/firefox/nightly/firstrun/"],"icon":"","lastUsed":1396514740},{"title":"Crossweave Test Page 3","urlHistory":["http://hg.mozilla.org/automation/crossweave/raw-file/2d9aca9585b6/pages/page3.html"],"icon":"","lastUsed":1396514740}]}  collection: tabs }
> Sync.Engine.Tabs  INFO  Uploading all of 1 records

FAIL:
> Sync.Store.Tabs TRACE Created tabs 1 of 1
> Sync.Store.Tabs TRACE Wrapping tab: {"title":"Firefox Nightly First Run Page","urlHistory":["http://www.mozilla.org/en-US/firefox/nightly/firstrun/"],"icon":"","lastUsed":1396510259}
> Sync.Engine.Tabs  TRACE Outgoing: { id: MDeg1-pbq1Sn  index: 0  modified: undefined  ttl: 604800  payload: {"id":"MDeg1-pbq1Sn","clientName":"profile2","tabs":[{"title":"Firefox Nightly First Run Page","urlHistory":["http://www.mozilla.org/en-US/firefox/nightly/firstrun/"],"icon":"","lastUsed":1396510259}]}  collection: tabs }
> Sync.Engine.Tabs  INFO  Uploading all of 1 records


PHASE3
---
We recieve those extra 2 Bookmark items mentioned in PHASE2

And
PASS: // 3 tabs
> Sync.Engine.Tabs  TRACE Incoming: { id: VTxjM8Cm73AP  index: 0  modified: 1396514741.31  ttl: 604800  payload: {"id":"VTxjM8Cm73AP","clientName":"profile2","tabs":[{"title":"Bye","urlHistory":["data:text/html,<html><head><title>Bye</title></head><body>Bye</body></html>"],"icon":"","lastUsed":1396514741},{"title":"Firefox Nightly First Run Page","urlHistory":["http://www.mozilla.org/en-US/firefox/nightly/firstrun/"],"icon":"","lastUsed":1396514740},{"title":"Crossweave Test Page 3","urlHistory":["http://hg.mozilla.org/automation/crossweave/raw-file/2d9aca9585b6/pages/page3.html"],"icon":"","lastUsed":1396514740}]}  collection: tabs }

FAIL: // 1 tab
> Sync.Engine.Tabs  TRACE Incoming: { id: MDeg1-pbq1Sn  index: 0  modified: 1396510260.4  ttl: 604800  payload: {"id":"MDeg1-pbq1Sn","clientName":"profile2","tabs":[{"title":"Firefox Nightly First Run Page","urlHistory":["http://www.mozilla.org/en-US/firefox/nightly/firstrun/"],"icon":"","lastUsed":1396510259}]}  collection: tabs }

[1] https://developer.mozilla.org/en/docs/Firefox_Sync/JavaScript_Client_API#The_Score

Comment 11

[Richard Newman [:rnewman]]

(In reply to Andrei Eftimie from comment #10)

> In the FAILING test we update the score twice (its just a 1 digit increase).
> That would mean the sync has a higher priority [1]. I don't see this
> affecting
> the test. We Sync at the end of the phase.

The score is only used for score-based scheduling. If you do enough stuff to bump the score over a threshold, a sync occurs.

The same sequence of actions should result in the same bumps to the score.

It's possible that the tabs listener isn't installed correctly, or the onTab handler is receiving some rolled-up combo event 'cos TPS is loading pages too quickly.


> > Sync.Store.Tabs TRACE Created tabs 3 of 3

> FAIL:
> > Sync.Store.Tabs TRACE Created tabs 1 of 1

And that's the bug: by the time Sync comes to do a sync, either the tabs are not yet open, or the tab open events have not been tracked.

It's possible that TPS simply isn't waiting long enough -- it adds the tab then rolls right on to syncing, but we need to wait for the tab to open before we sync.

Comment 12

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Yeah, that is what I thought yesterday. I did a quick check and indeed there is no call to this.StartAsyncOperation() in case of opening a tab. Not sure if other methods under tabs are affected too. But that smells like the problem.

Comment 13

[Andrei Eftimie]

We actually do call StartAsyncOperation():
http://dxr.mozilla.org/mozilla-central/source/services/sync/tps/extensions/tps/resource/tps.jsm#967

Comment 14

[Andrei Eftimie]

Attachment: testcase_bug990509.js

There's definitely something awry here.
Here's a simple testcase: we fail to verify 1 tab that we just added.

Comment 15

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Then it's most likely the "load" event we are waiting for. I think we should do it like Mozmill and wait for TabOpen / TabClose.

Comment 16

[Andrei Eftimie]

Attachment: WIP_1.patch

This patch is really rough. Even WIP is a longshot.

I've took what we had in mozmill-tests/lib/tabs.js in regards to `TabOpen` and `transitioned`. Also added a lot of boilerplate code to make this work.

This _might_ be a step in the right direction.
With this patch the testcase passes.

But test_tabs.js fail in phase to. I'm not sure yet, but I think we may again be to soon for the sync in step 1. We might need to wait for both the content load and the tabOpen + transitionend.

Comment 17

[Andrei Eftimie]

Comment on attachment 8401838 [details] [diff] [review]
WIP_1.patch

Whops, I created the patch with the files I wanted to ignore.

Comment 18

[Andrei Eftimie]

Attachment: WIP_1.1.patch

What I said in comment 16.
(+ this is a git patch)

Comment 19

[Andrei Eftimie]

Attachment: 0002-Bug-990509-Wait-for-TabOpen-and-TabTransition-instea.patch

This is rather disappointing. Attached is another WIP patch. We wait for all 3 events now: tabOpened, transitionend, load.

The testcase is passing.
If we call Verify right after Add we will have all entries.
But test_tabs.js is still failing for me.

I see it failing in phase2, because in Phase1 it did open both tabs, but it only synced one of them:
> 1396870191673 Sync.Store.Tabs TRACE Wrapping tab: {"title":"Firefox Nightly First Run Page","urlHistory":["http://www.mozilla.org/en-US/firefox/nightly/firstrun/"],"icon":"","lastUsed":1396870190}
> 1396870191673 Sync.Store.Tabs TRACE Wrapping tab: {"title":"Crossweave Test Page 1","urlHistory":["http://hg.mozilla.org/automation/crossweave/raw-file/2d9aca9585b6/pages/page1.html"],"icon":"","lastUsed":1396870190}
> 1396870191673 Sync.Engine.Tabs  TRACE Outgoing: { id: qYsSARA4Vjg8  index: 0  modified: undefined  ttl: 604800  payload: {"id":"qYsSARA4Vjg8","clientName":"profile1","tabs":[{"title":"Firefox Nightly First Run Page","urlHistory":["http://www.mozilla.org/en-US/firefox/nightly/firstrun/"],"icon":"","lastUsed":1396870190},{"title":"Crossweave Test Page 1","urlHistory":["http://hg.mozilla.org/automation/crossweave/raw-file/2d9aca9585b6/pages/page1.html"],"icon":"","lastUsed":1396870190}]}  collection: tabs }
> 1396870191676 Sync.Engine.Tabs  INFO  Uploading all of 1 records
Here we're missing the `data:text/html` tab.

Comment 20

[Henrik Skupin [:whimboo][⌚️UTC+2]]

It looks to me that this could be a core issue with sync, given that it detects the new tabs but don't sync them. Can you create a minimized testcase which shows this? Also please test with the old sync authentication. Does it work then?

Comment 21

[Andrei Eftimie]

Attachment: WIP1.3.patch

Just a small update. Still WIP.

Previous patch was blocking as it waited for all events to finish which would wreck the TPS async calls. This doesn't fix the problem we're having, there are some events that fire after they should if I read the log files correctly...

Comment 22

[Henrik Skupin [:whimboo][⌚️UTC+2]]

I still wonder if we really need all of those events. Have you checked based on which events Sync determines that a tab has been opened or closed? We have to wait at least that long.

Comment 23

[Andrei Eftimie]

I haven't managed to make any real progress here in the last days.
As discussed on IRC Henrik will take over.

Comment 24

[Henrik Skupin [:whimboo][⌚️UTC+2]]

So this is definitely a race-condition here. We are creating the tabs and they are getting recognized, but when it comes to the upload we currently only upload the initial welcome page. None of the other opened tabs are getting synced. This is happening already in phase 1 for me.

Comment 25

[Henrik Skupin [:whimboo][⌚️UTC+2]]

So the reason why this is working for the old sync authentication but not for Firefox Accounts is the fact that with the latter we do not fake a Weave login. I moved the following two lines in the auth module for sync because I thought it would only apply to it. But it looks like we also need it for Firefox Accounts. 

    // Fake the login
    Weave.Service.login();
    Weave.Svc.Obs.notify("weave:service:setup-complete");

While for the old sync both lines are necessary, for Firefox Account we only have to call Weave.Service.login().

Richard or Chris, is that something we should do or is that plainly wrong? For me it looks suspicious. I thought this is getting done automatically by setSignedInUser(). Might it be missing there?

Comment 26

[Henrik Skupin [:whimboo][⌚️UTC+2]]

So I checked all of our code via MXR and as it looks like the client code has to call it. In fact Firefox Account shouldn't do that because sync is basically not known for it given that it is a generic authentication module. So the patch I have locally should made it.

Comment 27

[Henrik Skupin [:whimboo][⌚️UTC+2]]

With the patch all other failures of the same type are gone, but test_tabs.js is still failing. It looks like that tabs for the other client are getting removed.

Comment 28

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Might be we have to combine the patches from Andrei and myself to get it working. While my patch fixed the interaction with Sync itself, the remaining problem seem to be related to detecting tabs. A simple test like this fails:

Phase('phase1', [
  [Tabs.add, tabs1],
  [Sync],
  [Tabs.verify, tabs1]
]);

Here all of the tabs opened should have been tracked, synced, and should be still around.

Comment 29

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Richard or Chris, what I don't understand is how to retrieve the tracked tabs for the current client? Lets say in profile 1 I create a couple of tabs, and want to verify that all are tracked by the tabs engine. When I call tabsEngine.getAllClients() I get back an empty array. Why is that, and why profile1 is not listed with its tabs? If that is the wrong way to retrieve that data, how can I do that? Or will that method only return the tabs for other clients except the current one?

Comment 30

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Given the current lack of information, I will leave this bug for test_tabs.js, and file a new bug for the fix for all the other tab related issues. Their fix should not be blocked by the problem as given on this bug. Would still be great to get the requested information.

Comment 31

[Chris Karlof [:ckarlof]]

Henrik, unfortunately my understanding of the Tabs engine is fairly limited. rnewman can likely help, or least you point you towards who can.

Comment 32

[Richard Newman [:rnewman]]

(In reply to Henrik Skupin (:whimboo) from comment #29)
> Richard or Chris, what I don't understand is how to retrieve the tracked
> tabs for the current client?

For the current client: 

  Weave.Service.engineManager.get("tabs")._store.getAllTabs()


> Lets say in profile 1 I create a couple of
> tabs, and want to verify that all are tracked by the tabs engine. When I
> call tabsEngine.getAllClients() I get back an empty array. Why is that, and
> why profile1 is not listed with its tabs?

This should explain:

  // API for use by Weave UI code to give user choices of tabs to open:
  getAllClients: function TabEngine_getAllClients() {
    return this._store._remoteClients;
  },

Comment 33

[Henrik Skupin [:whimboo][⌚️UTC+2]]

I will continue on this bug once bug 1003250 has been fixed, given that it is one symptom why this test is failing.

Comment 34

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Bug 1003250 actually fixed that problem.

Comment 35

[Henrik Skupin [:whimboo][⌚️UTC+2]]

We are still seeing this problem. :/ Chris can reproduce on his machine, while I cannot see it on my box. We might need more debug logs here.

Comment 36

[Chris Tung [:ctung]]

This is the output I get when i get the error - http://pastebin.com/dAKaa1ir
(this is using --binary on my nightly download i got from nightly.mozilla.org)

Comment 37

[Chris Tung [:ctung]]

(In reply to Chris Tung [:ctung] from comment #36)
> This is the output I get when i get the error - http://pastebin.com/dAKaa1ir
> (this is using --binary on my nightly download i got from
> nightly.mozilla.org)

and this is the output i get when i run it with my local firefox build - http://pastebin.com/eihFjZm7

Comment 38

[Chris Tung [:ctung]]

Attachment: --debug output

Comment 39

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Comment on attachment 8438701 [details]
--debug output

Chris, can you please add this output as plain text? Thanks.

Comment 40

[Chris Tung [:ctung]]

Attachment: --debug output for test_tabs

Comment 41

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Chris, sorry for the delay here. I totally missed to reply in time and then the bugmail went down in my inbox. :(

So I have taken a look at this failure and have seen the following...

In test3 we want to check if all the tabs added in test2 are present. Sadly this doesn't succeed because "data:text/html,<html><head><title>Bye</title></head><body>Bye</body></html>" hasn't been synced to profile 1. Here the excerpt from the debug log:

1402520844062	Sync.Engine.History	TRACE	Preparing 1 outgoing records
1402520844067	Sync.Engine.History	TRACE	Outgoing: { id: oH80tIRYQhhi  index: 100  modified: undefined  ttl: 5184000  payload: {"id":"oH80tIRYQhhi","histUri":"http://hg.mozilla.org/automation/crossweave/raw-file/2d9aca9585b6/pages/page3.html","title":"Crossweave Test Page 3","visits":[{"date":1402520843929304,"type":1}]}  collection: history }
1402520844067	Sync.Engine.History	INFO	Uploading all of 1 records

Chris, would you mind to replace this data URL with a real URL and check if that gets synced? I wonder if that issue is somewhat partly caused by data urls.

Comment 42

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Hi Chris, have you had any look in the past two weeks to get more details here?

Comment 43

[Chris Tung [:ctung]]

Hi Henrik, I am sorry I have had a whirlwind of the past month, only just saw your two updates to this.  I will get you an update within the next 2 days

Comment 44

[Chris Tung [:ctung]]

Henrik where would I find the line to replace the data URL with a real one?  And by real one do you mean just something simple as http://hg.mozilla.org/automation?

Comment 45

[Henrik Skupin [:whimboo][⌚️UTC+2]]

It's in the test this bug is about. You can find it here:
http://mxr.mozilla.org/mozilla-central/source/services/sync/tests/tps/test_tabs.js

There are actually two data url entries, you might want to replace.

Comment 46

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Chris will not have the time to finish this bug. So putting it back into the general bucket for someone else.

Cosmin, might you be able to check that during the next two weeks? This is really a failure which happens all the time on the machines we run in SCL3.

Comment 47

[Cosmin Malutan, [:cosmin-malutan]]

I'm not able to reproduce this issue, I adjusted the test to add more tabs but I still can't reproduce it. I wonder if someone else can reproduce this issue.
From what I saw in your both logs Cris:
> addons.manager  WARN    Exception calling callback: [Exception... "Component returned failure code: 0x8050000e (NS_ERROR_ILLEGAL_INPUT) [nsIScriptableUnicodeConverter.ConvertToUnicode]"  nsresult: "0x8050000e (NS_ERROR_ILLEGAL_INPUT)"  location: "JS frame :: resource://mozmill/modules/mozmill.js :: <TOP_LEVEL> :: line 113"  data: no] Stack trace: 
show that mozmill.js file is under modules directory but as you can see in the link below it's no longer located in modules directory but in driver.
https://github.com/mozilla/gecko-dev/tree/master/services/sync/tps/extensions/mozmill/resource/modules
Chris can you check if you have the latest TPS version?

Comment 48

[Cosmin Malutan, [:cosmin-malutan]]

I could reproduce this locally when I changed the remote testing page to our slow loading page:
>http://mozqa.com/data/firefox/layout/delayed_load.php?seconds=5
With this the failure is 100% reproducible so I'll continue to work on this tomorrow.
I think this reproduces on Chris machine because it's probably more remote from the mercurial server which host the page and it takes longer to load, but with our slow loading page we should be able to test this and get it fixed.

Comment 49

[Cosmin Malutan, [:cosmin-malutan]]

My bad here, it failed because I didn't updated the tab title in tests too, so I don't have testcase yet.

Comment 50

[Cosmin Malutan, [:cosmin-malutan]]

It looks like this reproduces on CI nodes, and we need to wait after we open the tab. So far I waited for events: transitioned, tabOpen, loaded; but only a sleep helped so it might be a different event.

Comment 51

[Cosmin Malutan, [:cosmin-malutan]]

I didn't find any topic to wait for, as I said it still works with a delay, also when it fails, after adding the tabs it doesn't do the sync:
>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: test phase 1: PASS
>CROSSWEAVE INFO: ----------event observed: quit-application-requested

>CROSSWEAVE TEST PASS: executing action ADD on tabs
>CROSSWEAVE INFO: test phase 1: PASS
>CROSSWEAVE INFO: ----------event observed: quit-application-requested
>CROSSWEAVE INFO: test phase 1: PASS

Comment 52

[Cosmin Malutan, [:cosmin-malutan]]

Attachment: patch v2.0

Looks to me that this has nothing to do with tabs opening, as I waited for all events we do wait in mozmill tests when we open tabs and I still had the same issue.
We fail to sync the tabs because we call FinishAsyncOperation function to early, and as in other places we just added a delay I did that here, and the problem is gone.
See the cases below:
https://github.com/mozilla/gecko-dev/blob/RELEASE_BASE_20140602/services/sync/tps/extensions/tps/resource/tps.jsm#L559
https://github.com/mozilla/gecko-dev/blob/RELEASE_BASE_20140602/services/sync/tps/extensions/tps/resource/tps.jsm#L211

Comment 53

[Andrei Eftimie]

Comment on attachment 8461463 [details] [diff] [review]
patch v2.0

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

Well, since this is the way this has been fixed for other calls to FinishAsyncOperation, its probably fine.
But I probably don't understand all implications this might have on the TPS framework, and I'm not a peer on TPS, so I'm providing a feedback + and leaving the review for someone more knowledgeable about TPS.

Comment 54

[Richard Newman [:rnewman]]

Comment on attachment 8461463 [details] [diff] [review]
patch v2.0

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

I think a 1-second delay is an awful hack. If this works running on the next tick instead, then do that (CommonUtils.nextTick). Otherwise, comment to explain why you're delaying.

Comment 55

[Cosmin Malutan, [:cosmin-malutan]]

It doesn't work to ran on nextTick. The thing is that we have to wait after we open the tabs, otherwise they won't be synced. I tried to wait for all events we do wait in our mozmill tests but it wasn't enough. I can have a deeper look in to this but I can't promise I will find a better solution.

Comment 56

[Cosmin Malutan, [:cosmin-malutan]]

I worked on this in the past day, and I didn't made any progress, no matter on for which events I wait I still get this failure. After opening the tabs we have to wait a second before starting the sync process, otherwise it won't sync the tabs and we get the test failure from summary.
As I mentioned in comment 52 we use this hack in other places too, so I don't think is that bad if it makes the tests pass and is not a sync services issue.
What do you say Richard, can we go ahead with this?

Comment 57

[Richard Newman [:rnewman]]

Yup; as I mentioned in Comment 54, just leave a comment in the code to explain why you're delaying.

Comment 58

[Cosmin Malutan, [:cosmin-malutan]]

Attachment: patch v2.1

I added the comment.

Comment 59

[Cosmin Malutan, [:cosmin-malutan]]

This needs to be checked it, it doesn't need a try build.

Comment 60

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/0501e0af5e57

Comment 61

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/0501e0af5e57

Comment 62

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/3a69e32cb54b
https://hg.mozilla.org/releases/mozilla-beta/rev/51f2c08f86ee

Comment 63

[Henrik Skupin [:whimboo][⌚️UTC+2]]

(In reply to Cosmin Malutan from comment #58)
> Created attachment 8465246 [details] [diff] [review]
> patch v2.1
> 
> I added the comment.

When you add a comment you should also give a reference to the bug #. Otherwise it's getting harder to figure out why it has been put into the file.

I hope that we can get rid of all those delays once we make TPS async itself.

When checking the tps testruns from the last days, no more failures are visible! So this fix made all work. Thanks Cosmin!