1183178 - Intermittent browser_mozLoop_context.js | Uncaught exception - at chrome://mochitests/content/browser/browser/components/loop/test/mochitest/head.js:246 - Error: Timed out while waiting for a 'load'' event | Found an unexpected tab at the end of test run

Status: RESOLVED FIXED

(Hello (Loop) :: Client, defect)

Description

[Ryan VanderMeulen [:RyanVM]]

07:55:13 INFO - 282 INFO checking window state
07:55:13 INFO - 283 INFO Entering test loadLoopPanel
07:55:13 INFO - 284 INFO Console message: [JavaScript Error: "The Components object is deprecated. It will soon be removed." {file: "chrome://browser/content/loop/shared/js/utils.js" line: 9}]
07:55:13 INFO - 285 INFO Leaving test loadLoopPanel
07:55:13 INFO - 286 INFO Entering test test_mozLoop_getSelectedTabMetadata
07:55:13 INFO - 287 INFO TEST-PASS | browser/components/loop/test/mochitest/browser_mozLoop_context.js | mozLoop should exist - {"userProfile":null,"doNotDisturb":false,"errors":{},"locale":"en-US","addBrowserSharingListener":"function addBrowserSharingLis == true
07:55:13 INFO - 288 INFO TEST-PASS | browser/components/loop/test/mochitest/browser_mozLoop_context.js | URL should be empty for about:blank - null === null
07:55:13 INFO - 289 INFO TEST-PASS | browser/components/loop/test/mochitest/browser_mozLoop_context.js | Favicon should be empty for about:blank - null === null
07:55:13 INFO - 290 INFO TEST-PASS | browser/components/loop/test/mochitest/browser_mozLoop_context.js | Title should be empty for about:blank - "" === ""
07:55:13 INFO - 291 INFO TEST-PASS | browser/components/loop/test/mochitest/browser_mozLoop_context.js | No previews available for about:blank - [] deepEqual []
07:55:13 INFO - 292 INFO Wait tab event: load
07:55:13 INFO - 293 INFO Console message: [JavaScript Error: "Error: operation not possible on dead CPOW" {file: "resource://gre/modules/RemoteAddonsParent.jsm" line: 568}]
07:55:13 INFO - 294 INFO Console message: 1436799312987 Toolkit.GMP WARN GMPInstallManager.parseResponseXML got node name: html, expected: updates
07:55:13 INFO - 295 INFO Console message: [JavaScript Error: "1436799312988 Toolkit.GMP ERROR GMPInstallManager.simpleCheckAndInstall Could not check for addons: {"target":{},"message":"got node name: html, expected: updates"}" {file: "resource://gre/modules/Log.jsm" line: 749}]
07:55:13 INFO - 296 INFO TEST-UNEXPECTED-FAIL | browser/components/loop/test/mochitest/browser_mozLoop_context.js | Uncaught exception - at chrome://mochitests/content/browser/browser/components/loop/test/mochitest/head.js:246 - Error: Timed out while waiting for a 'load'' event
07:55:13 INFO - Stack trace:
07:55:13 INFO - promiseTabLoadEvent/</timeout<@chrome://mochitests/content/browser/browser/components/loop/test/mochitest/head.js:246:14
07:55:13 INFO - Promise*promiseGetMozLoopAPI@chrome://mochitests/content/browser/browser/components/loop/test/mochitest/head.js:24:1
07:55:13 INFO - loadLoopPanel@chrome://mochitests/content/browser/browser/components/loop/test/mochitest/head.js:129:10
07:55:13 INFO - Tester_execTest/<@chrome://mochikit/content/browser-test.js:746:21
07:55:13 INFO - Tester_execTest@chrome://mochikit/content/browser-test.js:741:9
07:55:13 INFO - Tester.prototype.nextTest</<@chrome://mochikit/content/browser-test.js:664:7
07:55:13 INFO - SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:746:59
07:55:13 INFO - 297 INFO Leaving test test_mozLoop_getSelectedTabMetadata
07:55:13 INFO - 298 INFO Entering test test_mozLoop_getSelectedTabMetadata_defaultIcon

Comment 1

[Legacy TBPL/Treeherder Robot]

log: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-aurora&job_id=948243
repository: mozilla-aurora
start_time: 2015-07-13T07:38:40
who: rvandermeulen[at]mozilla[dot]com
machine: tst-linux64-spot-1158
buildname: Ubuntu VM 12.04 x64 mozilla-aurora debug test mochitest-e10s-browser-chrome-2
revision: b40e564b656b

296 INFO TEST-UNEXPECTED-FAIL | browser/components/loop/test/mochitest/browser_mozLoop_context.js | Uncaught exception - at chrome://mochitests/content/browser/browser/components/loop/test/mochitest/head.js:246 - Error: Timed out while waiting for a 'load'' event
308 INFO TEST-UNEXPECTED-FAIL | browser/components/loop/test/mochitest/browser_mozLoop_context.js | Found an unexpected tab at the end of test run: about:home - expected PASS

Comment 2

[Legacy TBPL/Treeherder Robot]

log: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=11646286
repository: mozilla-inbound
start_time: 2015-07-13T21:40:04
who: tomcat[at]mozilla[dot]com
machine: tst-linux64-spot-1330
buildname: Ubuntu VM 12.04 x64 mozilla-inbound opt test mochitest-e10s-browser-chrome-3
revision: e974d344bf02

68 INFO TEST-UNEXPECTED-FAIL | browser/components/loop/test/mochitest/browser_mozLoop_context.js | Uncaught exception - at chrome://mochitests/content/browser/browser/components/loop/test/mochitest/head.js:246 - Error: Timed out while waiting for a 'load'' event
71 INFO TEST-UNEXPECTED-FAIL | browser/components/loop/test/mochitest/browser_mozLoop_context.js | Found an unexpected tab at the end of test run: http://example.com/ - expected PASS

Comment 3

[Legacy TBPL/Treeherder Robot]

log: https://treeherder.mozilla.org/logviewer.html#?repo=b2g-inbound&job_id=2326855
repository: b2g-inbound
start_time: 2015-07-16T08:06:18
who: rvandermeulen[at]mozilla[dot]com
machine: tst-linux32-spot-372
buildname: Ubuntu VM 12.04 b2g-inbound pgo test mochitest-e10s-browser-chrome-1
revision: 408fbd548768

685 INFO TEST-UNEXPECTED-FAIL | browser/components/loop/test/mochitest/browser_mozLoop_context.js | Uncaught exception - at chrome://mochitests/content/browser/browser/components/loop/test/mochitest/head.js:246 - Error: Timed out while waiting for a 'load'' event
696 INFO TEST-UNEXPECTED-FAIL | browser/components/loop/test/mochitest/browser_mozLoop_context.js | Found an unexpected tab at the end of test run: about:home - expected PASS

Comment 4

[Mike de Boer [:mikedeboer]]

So this is what I see repeating in the logs each time this test fails:

```
07:55:13 INFO - 292 INFO Wait tab event: load
07:55:13 INFO - 293 INFO Console message: [JavaScript Error: "Error: operation not possible on dead CPOW" {file: "resource://gre/modules/RemoteAddonsParent.jsm" line: 568}]
```

What this test does is:
 1) open a new tab,
 2) load 'http://example.com' in it,
 3) wait for the 'load' event to continue testing.

What I'm curious about `Prefetcher.withPrefetching` in RemoteAddonsParent.jsm is doing here that might interfere with the loading process?
Does it have to do with the fact that I'm using the 'example.com' domain that might be used by some channel for a remote addon? - disclaimer: wild, unsubstantiated wild guess :)

Comment 5

[Mike Conley (:mconley) (:⚙️)]

(In reply to Mike de Boer [:mikedeboer] from comment #4)
> So this is what I see repeating in the logs each time this test fails:
> 
> ```
> 07:55:13 INFO - 292 INFO Wait tab event: load
> 07:55:13 INFO - 293 INFO Console message: [JavaScript Error: "Error:
> operation not possible on dead CPOW" {file:
> "resource://gre/modules/RemoteAddonsParent.jsm" line: 568}]
> ```
> 
> What this test does is:
>  1) open a new tab,
>  2) load 'http://example.com' in it,
>  3) wait for the 'load' event to continue testing.
> 
> What I'm curious about `Prefetcher.withPrefetching` in
> RemoteAddonsParent.jsm is doing here that might interfere with the loading
> process?
> Does it have to do with the fact that I'm using the 'example.com' domain
> that might be used by some channel for a remote addon? - disclaimer: wild,
> unsubstantiated wild guess :)

I don't know the test too well, but perhaps instead of using promiseTabLoadEvent, use BrowserTestUtils.loadURI, and BrowserTestUtils.browserLoaded. Both have been designed to work nicely cross-process, instead of using the addon shims (which having the parent listen for DOM events causes us to use).

Example:

yield BrowserTestUtils.loadURI(browser, "http://example.com");
yield BrowserTestUtils.browserLoaded(browser);

Perhaps that'd make this go away?

Comment 6

[Mike de Boer [:mikedeboer]]

Cool! I'll try that next week. Thanks, Mike!

Comment 7

[Mike de Boer [:mikedeboer]]

Attachment: Patch v1: use more robust e10s-friendly tab loading mechanism

Comment 8

[Mike de Boer [:mikedeboer]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=1cb3ab9741bb

Comment 9

[Mark Banner (:standard8)]

Comment on attachment 8635930 [details] [diff] [review]
Patch v1: use more robust e10s-friendly tab loading mechanism

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

Looks fine so r=Standard8. One thought though - should we be removing the use of promiseTabLoadEvent from our other tests & from head.js, with the intention of dropping the function from head.js completely?

Comment 10

[Mike de Boer [:mikedeboer]]

Attachment: Patch v2: use more robust e10s-friendly tab loading mechanism

Good point! I was being too conservative here...

Comment 11

[Mike de Boer [:mikedeboer]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=d7fe889e1611

Comment 12

[Mark Banner (:standard8)]

Comment on attachment 8636547 [details] [diff] [review]
Patch v2: use more robust e10s-friendly tab loading mechanism

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

Great!

Comment 13

[Pulsebot]

https://hg.mozilla.org/integration/fx-team/rev/72afb470c307

Comment 14

[Pulsebot]

https://hg.mozilla.org/integration/fx-team/rev/39db7984852a

Comment 15

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/72afb470c307
https://hg.mozilla.org/mozilla-central/rev/39db7984852a

Comment 16

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/d139de71e663

Comment 17

[Legacy TBPL/Treeherder Robot]

log: https://treeherder.mozilla.org/logviewer.html#?repo=b2g-inbound&job_id=2675016
repository: b2g-inbound
start_time: 2015-09-03T16:13:52
who: tomcat[at]mozilla[dot]com
machine: t-snow-r4-0088
buildname: Rev4 MacOSX Snow Leopard 10.6 b2g-inbound opt test mochitest-e10s-browser-chrome-2
revision: 0470ac7361ef

710 INFO TEST-UNEXPECTED-FAIL | browser/components/loop/test/mochitest/browser_mozLoop_appVersionInfo.js | uncaught exception - TypeError: can't access dead object at chrome://browser/content/tabbrowser.xml:3486
733 INFO TEST-UNEXPECTED-FAIL | browser/components/loop/test/mochitest/browser_mozLoop_context.js | Test timed out - expected PASS
735 INFO TEST-UNEXPECTED-FAIL | browser/components/loop/test/mochitest/browser_mozLoop_context.js | Found a tab after previous test timed out: about:home - expected PASS