935474 - Test failure 'controller.waitForPageLoad(): Timeout waiting for page loaded.' in testBookmarks_OpenAllInTabs/test1.js

Status: RESOLVED FIXED

(Mozilla QA Graveyard :: Mozmill Tests, defect, P1)

Description

[Andrei Eftimie]

Module:    testOpenAllBookmarksInTabs
Test:      testBookmarks_OpenAllInTabs/test1.js    
Failure:   controller.waitForPageLoad(): Timeout waiting for page loaded.
Branches:  default
Platforms: OSX

Only affects mozmill 2.0, mozmill 1.5 works fine.

Marking as P1 since it has a 100% reproducible rate (at least on OSX).
We should try getting this fixed before we start running 2.0 in ci.

Here is an example report:
http://mozmill-crowd.blargon7.com/#/endurance/report/d17690a112360a2b3155acaa276f1bac

Comment 1

[Henrik Skupin [:whimboo][⌚️UTC+2] (away 07/21 - 08/08)]

Is this a regression? We haven't seen this before. Can you work on this bug Andrei?

Comment 2

[Andrei Eftimie]

Checking if its a mozmill or a mozmill-tests issue

Comment 3

[Andrei Eftimie]

We fail in the closeAllTabs() method:
http://hg.mozilla.org/qa/mozmill-tests/file/7d43ed60222f/lib/tabs.js#l164

> this._controller.open(this._controller.window.BROWSER_NEW_TAB_URL);
> this._controller.waitForPageLoad();

Comment 4

[Andrei Eftimie]

Hope this would go away with the recent changes to open/close tabs from bug 890181 (which hasn't landed yet), but the problem persists with that patch applied.

Comment 5

[Henrik Skupin [:whimboo][⌚️UTC+2] (away 07/21 - 08/08)]

Andrei, is that failure fixed now?

Comment 6

[Andrei Eftimie]

I can still reproduce this.
I'll work to figure this out now.

Comment 7

[Andrei Eftimie]

We fail in closeAllTabs() while waiting for the 'about:blank' page to load.

> * current map: {"3":{"loaded":true},"7":{"loaded":true,"id_load_in_transition":{"name":"","number":"{1e92f596-8571-ac4f-a137-502b03118802}","valid":true},"id_load_handled":{"name":"","number":"{1e92f596-8571-ac4f-a137-502b03118802}","valid":true}}}
> ** Page has been finished loading: id=7, status=false, uuid={1e92f596-8571-ac4f-a137-502b03118802}
> *** 'pagehide' event: id=7, baseURI=about:newtab
> * current map: {"3":{"loaded":true},"7":{"loaded":false,"id_load_in_transition":{"name":"","number":"{1e92f596-8571-ac4f-a137-502b03118802}","valid":true},"id_load_handled":{"name":"","number":"{1e92f596-8571-ac4f-a137-502b03118802}","valid":true}}}
> * current map: {"3":{"loaded":true},"7":{"loaded":false,"id_load_in_transition":{"name":"","number":"{b87d84f5-fd7d-af4b-bae3-df50255b2117}","valid":true},"id_load_handled":{"name":"","number":"{1e92f596-8571-ac4f-a137-502b03118802}","valid":true}}}
> *** Page status updated: id=7, loaded=false, uuid={b87d84f5-fd7d-af4b-bae3-df50255b2117}
> *** 'DOMContentLoaded' event: id=7, baseURI=about:newtab
> *** 'pageshow' event: id=7, baseURI=about:newtab
> * current map: {"3":{"loaded":true},"7":{"loaded":true,"id_load_in_transition":{"name":"","number":"{b87d84f5-fd7d-af4b-bae3-df50255b2117}","valid":true},"id_load_handled":{"name":"","number":"{1e92f596-8571-ac4f-a137-502b03118802}","valid":true}}}
> *** Page status updated: id=7, loaded=true, uuid={b87d84f5-fd7d-af4b-bae3-df50255b2117}
> * current map: {"3":{"loaded":true},"7":{"loaded":true,"id_load_in_transition":{"name":"","number":"{b87d84f5-fd7d-af4b-bae3-df50255b2117}","valid":true},"id_load_handled":{"name":"","number":"{b87d84f5-fd7d-af4b-bae3-df50255b2117}","valid":true}}}
> ** Page has been finished loading: id=7, status=true, uuid={b87d84f5-fd7d-af4b-bae3-df50255b2117}
> ** Page has been finished loading: id=7, status=false, uuid={b87d84f5-fd7d-af4b-bae3-df50255b2117}
> ** Page has been finished loading: id=7, status=false, uuid={b87d84f5-fd7d-af4b-bae3-df50255b2117}

Comment 8

[mario garbi]

Happened with Mozmill 2.0 on OSX 10.7.5 and Firefox 27:
http://mozmill-daily.blargon7.com/#/endurance/report/b99421c0f132c68dec1548288a4141de

Comment 9

[Andrei Eftimie]

Attachment: testcase.js

I've reduced this failure to the attached testcase.

We basically come down to calling waitForPageLoad() twice for the same page.
This is due to a combination between waitForPageLoad() and closeAllTabs()

This fails in 2.0 but passes in 1.5

I'll look into what has caused this.
Bug 885221 might be the culprit https://github.com/mozilla/mozmill/commit/05f859f618fb89f789d0c12fd1574f09e98fa0e9

Comment 10

[Andrei Eftimie]

Well, this is case on the mozmill 2.0 codebase since at least early 2011.

The question is:

Should this fail or not?
> controller.waitForPageLoad();
> controller.waitForPageLoad();

I agree that we shouldn't have these calls in our tests, we do end up calling waitForPageLoad() on the same page twice in the case of this particular failure.

Should:

1) we amend the test (or lib) so this doesn't happen
2) mozmill be able to handle this gracefully?

Comment 11

[Henrik Skupin [:whimboo][⌚️UTC+2] (away 07/21 - 08/08)]

(In reply to Andrei Eftimie from comment #10) 
> Should this fail or not?
> > controller.waitForPageLoad();
> > controller.waitForPageLoad();
> 
> I agree that we shouldn't have these calls in our tests, we do end up
> calling waitForPageLoad() on the same page twice in the case of this
> particular failure.

This code example is invalid and should never been used, right! You cannot call it twice without having any unload in between.

> 2) mozmill be able to handle this gracefully?

No. That is against the design decisions.

Comment 12

[Andrei Eftimie]

Attachment: 1.patch

I've found and fixed the real issue.

We were getting to the point of calling waitForPageLoad() on the same page ('about:blank') because on subsequent iterations we would fail clicking on the  `testFolder` - the new pages would fail opening, and we would check the first tab again.

Both the `testFolder` and the `openAllInTabs` are chrome elements, so we can safely retrieve them before the endurance loop. This should also improve performance a bit (probably not by any significant mean).

Comment 13

[Andrei Eftimie]

Mozmill 2: http://mozmill-crowd.blargon7.com/#/endurance/report/b99421c0f132c68dec1548288a52c41f
Mozmill 1.5: http://mozmill-crowd.blargon7.com/#/endurance/report/b99421c0f132c68dec1548288a52ba3e

Comment 14

[Andreea Matei [:AndreeaMatei]]

Comment on attachment 8340250 [details] [diff] [review]
1.patch

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

Looks right. Not sure if it's not worth investigating further why this happens only with 2.0. But landed:
http://hg.mozilla.org/qa/mozmill-tests/rev/ae5afd539ab8 (default)

Comment 15

[Andrei Eftimie]

Attachment: esr17_1.patch

Applies cleanly to all branches except ESR17 for which the attached patch is for.

Comment 16

[Andreea Matei [:AndreeaMatei]]

Comment on attachment 8340335 [details] [diff] [review]
esr17_1.patch

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

Transplanted:
http://hg.mozilla.org/qa/mozmill-tests/rev/6f6e879e2210 (aurora)
http://hg.mozilla.org/qa/mozmill-tests/rev/d7af8c0afd8f (beta)
http://hg.mozilla.org/qa/mozmill-tests/rev/5d12df554b66 (release)
http://hg.mozilla.org/qa/mozmill-tests/rev/8f8fc67fe41b (esr24)
http://hg.mozilla.org/qa/mozmill-tests/rev/aa84416ebce6 (esr17)

Thanks!