1630211 - Intermittent toolkit/components/pictureinpicture/tests/<test_name>| Uncaught exception - at resource://testing-common/BrowserTestUtils.jsm:1000 - TypeError: can't access property "getAttribute", win.document.documentElement is null

Status: RESOLVED FIXED

(Toolkit :: Video/Audio Controls, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: shindli [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=297701213&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/JGUfgcGGRZ6UC-1x1Jnitg/runs/0/artifacts/public/logs/live_backing.log

---

task 2020-04-15T09:14:21.308Z] 09:14:21 INFO - TEST-PASS | toolkit/components/pictureinpicture/tests/browser_mouseButtonVariation.js | Toggle reached target opacity. - true == true -
[task 2020-04-15T09:14:21.308Z] 09:14:21 INFO - Clicking on toggle, and expecting a Picture-in-Picture window to open
[task 2020-04-15T09:14:21.309Z] 09:14:21 INFO - TEST-PASS | toolkit/components/pictureinpicture/tests/browser_mouseButtonVariation.js | A Picture-in-Picture window opened. -
[task 2020-04-15T09:14:21.309Z] 09:14:21 INFO - Buffered messages finished
[task 2020-04-15T09:14:21.309Z] 09:14:21 INFO - TEST-UNEXPECTED-FAIL | toolkit/components/pictureinpicture/tests/browser_mouseButtonVariation.js | Uncaught exception - at resource://testing-common/BrowserTestUtils.jsm:1000 - TypeError: can't access property "getAttribute", win.document.documentElement is null
[task 2020-04-15T09:14:21.309Z] 09:14:21 INFO - Stack trace:
[task 2020-04-15T09:14:21.309Z] 09:14:21 INFO - windowClosed@resource://testing-common/BrowserTestUtils.jsm:1000:19
[task 2020-04-15T09:14:21.309Z] 09:14:21 INFO - closeWindow@resource://testing-common/BrowserTestUtils.jsm:981:42
[task 2020-04-15T09:14:21.309Z] 09:14:21 INFO - @chrome://mochitests/content/browser/toolkit/components/pictureinpicture/tests/browser_mouseButtonVariation.js:83:30
[task 2020-04-15T09:14:21.309Z] 09:14:21 INFO - asyncwithNewTab@resource://testing-common/BrowserTestUtils.jsm:150:24
[task 2020-04-15T09:14:21.309Z] 09:14:21 INFO - async@chrome://mochitests/content/browser/toolkit/components/pictureinpicture/tests/browser_mouseButtonVariation.js:14:26
[task 2020-04-15T09:14:21.309Z] 09:14:21 INFO - Tester_execTest/<@chrome://mochikit/content/browser-test.js:1039:34
[task 2020-04-15T09:14:21.309Z] 09:14:21 INFO - Tester_execTest@chrome://mochikit/content/browser-test.js:1074:11
[task 2020-04-15T09:14:21.310Z] 09:14:21 INFO - nextTest/<@chrome://mochikit/content/browser-test.js:904:14
[task 2020-04-15T09:14:21.310Z] 09:14:21 INFO - SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:918:23
[task 2020-04-15T09:14:21.310Z] 09:14:21 INFO - Leaving test bound
[task 2020-04-15T09:14:21.310Z] 09:14:21 INFO - Console message: OpenGL compositor Initialized Succesfully.
[task 2020-04-15T09:14:21.310Z] 09:14:21 INFO - Version: 2.1 INTEL-12.9.22
[task 2020-04-15T09:14:21.310Z] 09:14:21 INFO - Vendor: Intel Inc.
[task 2020-04-15T09:14:21.310Z] 09:14:21 INFO - Renderer: Intel Iris OpenGL Engine
[task 2020-04-15T09:14:21.310Z] 09:14:21 INFO - FBO Texture Target: TEXTURE_2D
[task 2020-04-15T09:14:21.311Z] 09:14:21 INFO - Console message: OpenGL compositor Initialized Succesfully.
[task 2020-04-15T09:14:21.311Z] 09:14:21 INFO - Version: 2.1 INTEL-12.9.22
[task 2020-04-15T09:14:21.311Z] 09:14:21 INFO - Vendor: Intel Inc.
[task 2020-04-15T09:14:21.311Z] 09:14:21 INFO - Renderer: Intel Iris OpenGL Engine
[task 2020-04-15T09:14:21.311Z] 09:14:21 INFO - FBO Texture Target: TEXTURE_2D
[task 2020-04-15T09:14:21.311Z] 09:14:21 INFO - GECKO(2955) | MEMORY STAT | vsize 7697MB | residentFast 347MB | heapAllocated 117MB
[task 2020-04-15T09:14:21.311Z] 09:14:21 INFO - TEST-OK | toolkit/components/pictureinpicture/tests/browser_mouseButtonVariation.js | took 1164ms
[task 2020-04-15T09:14:21.311Z] 09:14:21 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-04-15T09:14:21.311Z] 09:14:21 INFO - TEST-UNEXPECTED-FAIL | toolkit/components/pictureinpicture/tests/browser_mouseButtonVariation.js | Found an unexpected tab at the end of test run: http://example.com/browser/toolkit/components/pictureinpicture/tests/test-page.html -
[task 2020-04-15T09:14:21.312Z] 09:14:21 INFO - checking window state
[task 2020-04-15T09:14:21.312Z] 09:14:21 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-04-15T09:14:21.312Z] 09:14:21 INFO - TEST-UNEXPECTED-FAIL | toolkit/components/pictureinpicture/tests/browser_mouseButtonVariation.js | Found an unexpected Toolkit:PictureInPicture at the end of test run -
[task 2020-04-15T09:14:21.312Z] 09:14:21 INFO - GECKO(2955) | must wait for focus
[task 2020-04-15T09:14:21.312Z] 09:14:21 INFO - TEST-START | toolkit/components/pictureinpicture/tests/browser_removeVideoElement.js
[task 2020-04-15T09:14:22.946Z] 09:14:22 INFO - GECKO(2955) | MEMORY STAT | vsize 7678MB | residentFast 349MB | heapAllocated 124MB
[task 2020-04-15T09:14:22.946Z] 09:14:22 INFO - TEST-OK | toolkit/components/pictureinpicture/tests/browser_removeVideoElement.js | took 1705ms
[task 2020-04-15T09:14:22.982Z] 09:14:22 INFO - checking window state
[task 2020-04-15T09:14:22.982Z] 09:14:22 INFO - TEST-START | toolkit/components/pictureinpicture/tests/browser_rerequestPiP.js
[task 2020-04-15T09:14:23.564Z] 09:14:23 INFO - GECKO(2955) | MEMORY STAT | vsize 7678MB | residentFast 349MB | heapAllocated 127MB
[task 2020-04-15T09:14:23.565Z] 09:14:23 INFO - TEST-OK | toolkit/components/pictureinpicture/tests/browser_rerequestPiP.js | took 584ms
[task 2020-04-15T09:14:23.577Z] 09:14:23 INFO - checking window state

[task 2020-04-15T09:21:51.163Z] 09:21:51 INFO - Buffered messages finished
[task 2020-04-15T09:21:51.164Z] 09:21:51 INFO - SUITE-END | took 1071s
[task 2020-04-15T09:21:51.228Z] 09:21:51 ERROR - Return code: 1
[task 2020-04-15T09:21:51.229Z] 09:21:51 ERROR - Got 3 unexpected statuses
[task 2020-04-15T09:21:51.229Z] 09:21:51 INFO - TinderboxPrint: mochitest-mochitest-browser-chrome<br/>673/<em class="testfail">3</em>/0
[task 2020-04-15T09:21:51.229Z] 09:21:51 WARNING - # TBPL WARNING #
[task 2020-04-15T09:21:51.229Z] 09:21:51 WARNING - setting return code to 1
[task 2020-04-15T09:21:51.229Z] 09:21:51 WARNING - The mochitest suite: mochitest-browser-chrome ran with return status: WARNING
[task 2020-04-15T09:21:51.229Z] 09:21:51 INFO - Running post-action listener: _package_coverage_data
[task 2020-04-15T09:21:51.229Z] 09:21:51 INFO - Running post-action listener: _resource_record_post_action
[task 2020-04-15T09:21:51.229Z] 09:21:51 INFO - Running post-action listener: process_java_coverage_data
[task 2020-04-15T09:21:51.229Z] 09:21:51 INFO - [mozharness: 2020-04-15 09:21:51.229891Z] Finished run-tests step (success)
[task 2020-04-15T09:21:51.230Z] 09:21:51 INFO - Running post-run listener: _resource_record_post_run
[task 2020-04-15T09:21:51.351Z] 09:21:51 INFO - instance_metadata.json not found; unable to determine instance type
[task 2020-04-15T09:21:51.354Z] 09:21:51 INFO - Validating Perfherder data against /Users/cltbld/tasks/task_1586936812/mozharness/external_tools/performance-artifact-schema.json
[task 2020-04-15T09:21:51.359Z] 09:21:51 INFO - PERFHERDER_DATA: {"framework": {"name": "job_resource_usage"}, "suites": [{"subtests": [{"name": "cpu_percent", "value": 19.2867802303263}, {"name": "io_write_bytes", "value": 3273940992}, {"name": "io.read_bytes", "value": 197783552}, {"name": "io_write_time", "value": 14466}, {"name": "io_read_time", "value": 2678}], "extraOptions": ["e10s", "buildbot-unknown"], "name": "mochitest.mochitest-browser-chrome.overall"}, {"subtests": [{"name": "time", "value": 0.0002770423889160156}], "name": "mochitest.mochitest-browser-chrome.start-pulseaudio"}, {"subtests": [{"name": "time", "value": 19.277751207351685}, {"name": "cpu_percent", "value": 37.91666666666667}], "name": "mochitest.mochitest-browser-chrome.install"}, {"subtests": [{"name": "time", "value": 0.00022292137145996094}], "name": "mochitest.mochitest-browser-chrome.stage-files"}, {"subtests": [{"name": "time", "value": 1073.0281989574432}, {"name": "cpu_percent", "value": 18.94978005865103}], "name": "mochitest.mochitest-browser-chrome.run-tests"}]}
[task 2020-04-15T09:21:51.359Z] 09:21:51 INFO - Total resource usage - Wall time: 1092s; CPU: 19.0%; Read bytes: 197783552; Write bytes: 3273940992; Read time: 2678; Write time: 14466
[task 2020-04-15T09:21:51.359Z] 09:21:51 INFO - TinderboxPrint: CPU usage<br/>18.9%
[task 2020-04-15T09:21:51.359Z] 09:21:51 INFO - TinderboxPrint: I/O read bytes / time<br/>197,783,552 / 2,678
[task 2020-04-15T09:21:51.359Z] 09:21:51 INFO - TinderboxPrint: I/O write bytes / time<br/>3,273,940,992 / 14,466
[task 2020-04-15T09:21:51.359Z] 09:21:51 INFO - TinderboxPrint: CPU idle<br/>2,913.4 (66.7%)
[task 2020-04-15T09:21:51.359Z] 09:21:51 INFO - TinderboxPrint: CPU system<br/>326.3 (7.5%)
[task 2020-04-15T09:21:51.359Z] 09:21:51 INFO - TinderboxPrint: CPU user<br/>1,127.9 (25.8%)
[task 2020-04-15T09:21:51.360Z] 09:21:51 INFO - TinderboxPrint: Swap in / out<br/>455,442,432 / 0
[task 2020-04-15T09:21:51.360Z] 09:21:51 INFO - start-pulseaudio - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2020-04-15T09:21:51.361Z] 09:21:51 INFO - install - Wall time: 19s; CPU: 38.0%; Read bytes: 274478592; Write bytes: 260751360; Read time: 14643; Write time: 496
[task 2020-04-15T09:21:51.362Z] 09:21:51 INFO - stage-files - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2020-04-15T09:21:51.370Z] 09:21:51 INFO - run-tests - Wall time: 1073s; CPU: 19.0%; Read bytes: 188416000; Write bytes: 2990174208; Read time: 2555; Write time: 13924
[task 2020-04-15T09:21:51.605Z] 09:21:51 WARNING - returning nonzero exit status 1
[fetches 2020-04-15T09:21:51.642Z] removing /Users/cltbld/tasks/task_1586936812/fetches
[fetches 2020-04-15T09:21:51.644Z] finished
[taskcluster 2020-04-15T09:21:51.654Z] Exit Code: 1
[taskcluster 2020-04-15T09:21:51.654Z] User Time: 17m19.359054s
[taskcluster 2020-04-15T09:21:51.654Z] Kernel Time: 3m46.934549s
[taskcluster 2020-04-15T09:21:51.654Z] Wall Time: 19m53.527509962s
[taskcluster 2020-04-15T09:21:51.654Z] Result: FAILED
[taskcluster 2020-04-15T09:21:51.655Z] === Task Finished ===
[taskcluster 2020-04-15T09:21:51.655Z] Task Duration: 19m53.531435321s
[taskcluster 2020-04-15T09:21:51.890Z] Uploading artifact public/logs/localconfig.json from file logs/localconfig.json with content encoding "gzip", mime type "application/json" and expiry 2021-04-15T07:11:15.998Z
[taskcluster 2020-04-15T09:21:52.419Z] Uploading artifact public/test_info/manifests.list from file build/blobber_upload_dir/manifests.list with content encoding "gzip", mime type "text/plain; charset=utf-8" and expiry 2021-04-15T07:11:15.998Z
[taskcluster 2020-04-15T09:21:52.666Z] Uploading artifact public/test_info/mochitest-browser-chrome_errorsummary.log from file build/blobber_upload_dir/mochitest-browser-chrome_errorsummary.log with content encoding "gzip", mime type "text/plain" and expiry 2021-04-15T07:11:15.998Z
[taskcluster 2020-04-15T09:21:52.921Z] Uploading artifact public/test_info/mochitest-browser-chrome_raw.log from file build/blobber_upload_dir/mochitest-browser-chrome_raw.log with content encoding "gzip", mime type "text/plain" and expiry 2021-04-15T07:11:15.998Z
[taskcluster 2020-04-15T09:21:55.471Z] Uploading artifact public/test_info/mozilla-test-fail-screenshot_59fGTb.png from file build/blobber_upload_dir/mozilla-test-fail-screenshot_59fGTb.png with content encoding "", mime type "image/png" and expiry 2021-04-15T07:11:15.998Z
[taskcluster 2020-04-15T09:21:58.760Z] Uploading artifact public/test_info/resource-usage.json from file build/blobber_upload_dir/resource-usage.json with content encoding "gzip", mime type "application/json" and expiry 2021-04-15T07:11:15.998Z
[taskcluster:error] exit status 1

Comment 1

[BugBot [:suhaib / :marco/ :calixte]]

Bugbug thinks this bug should belong to this component, but please revert this change in case of error.

Comment 2

[Noemi Erli[:noemi_erli]]

This seems to be fixed by backout of 1607984
https://treeherder.mozilla.org/#/jobs?repo=autoland&resultStatus=success%2Ctestfailed%2Cbusted%2Cexception&revision=cdf53efcd4c99729cd2853a9546f581e22c2cad1
Range where we can see that fails stops after the backout:
https://treeherder.mozilla.org/#/jobs?repo=autoland&searchStr=9ab9662defc13edcd6d1689d11b5b7692977ec05&tochange=9bf6c841e1d7fdd398fe8cd73ef53d6ccc99b9c6&fromchange=12283ed18e4a3f3ad5570ac2731963544b58db1d

Comment 3

[Intermittent Failures Robot]

19 failures in 967 pushes (0.02 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 19

Platform breakdown:

• macosx1014-64-shippable: 15
• linux1804-64-asan: 2
• windows10-64: 1
• windows7-32-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1630211&startday=2020-04-15&endday=2020-04-15&tree=all

Comment 4

[Intermittent Failures Robot]

19 failures in 4528 pushes (0.004 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 19

Platform breakdown:

• macosx1014-64-shippable: 15
• linux1804-64-asan: 2
• windows10-64: 1
• windows7-32-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1630211&startday=2020-04-13&endday=2020-04-19&tree=all

Comment 5

[Intermittent Failures Robot]

61 failures in 1125 pushes (0.054 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 61

Platform breakdown:

• linux1804-64-asan: 5
• windows10-64: 4
• macosx1014-64-shippable: 48
• linux1804-64-shippable: 1
• windows7-32-shippable: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1630211&startday=2020-04-24&endday=2020-04-24&tree=all

Comment 6

[Andreea Pavel [:apavel]]

Jean-Yves, this started spiking again when bug 1607984, with all it's fixes, relanded. Please take a look as the failure rate is very high.
Thank you.

Comment 7

[Jean-Yves Avenard [:jya]]

(In reply to Andreea Pavel [:apavel] from comment #6)

Jean-Yves, this started spiking again when bug 1607984, with all it's fixes, relanded. Please take a look as the failure rate is very high.
Thank you.

It can't be, because bug 1607984 push code that is disabled by default.

However, this push https://hg.mozilla.org/integration/autoland/rev/43b914eee3e3 enabled the code.

It's now revealing more buggy tests that I missed as they are all intermittent failures.

Comment 8

[Jean-Yves Avenard [:jya]]

Attachment: Bug 1630211 - Wait for the load to complete. r?gijs,mconley

Another case of opening a tab without waiting for the load to complete.

Comment 9

[Mark Banner (:standard8)]

toolkit/components/pictureinpicture/tests/browser_smallVideoLayout.js might also be another case:

https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=299408430&repo=try&lineNumber=8352

Comment 12

[Noemi Erli[:noemi_erli]]

Other occurrences:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=299268334&repo=autoland&lineNumber=16931 on browser_durationChange.js
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=299300406&repo=autoland&lineNumber=14972 on browser_toggleTransparentOverlay-1.js
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=299416792&repo=autoland&lineNumber=22238 on browser_smallVideoLayout.js

Comment 13

[Intermittent Failures Robot]

19 failures in 230 pushes (0.083 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 13
• mozilla-central: 2
• try: 4

Platform breakdown:

• linux1804-64-shippable: 4
• windows7-32-shippable: 1
• linux1804-64-asan: 3
• macosx1014-64-shippable: 6
• linux1804-64: 3
• windows10-64-qr: 1
• windows10-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1630211&startday=2020-04-25&endday=2020-04-25&tree=all

Comment 14

[Intermittent Failures Robot]

80 failures in 5582 pushes (0.014 failures/push) were associated with this bug in the last 7 days.

This is the #22 most frequent failure this week.

** This failure happened more than 75 times this week! Resolving this bug is a very high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 1 week, the affected test(s) may be disabled. **

Repository breakdown:

• autoland: 74
• mozilla-central: 2
• try: 4

Platform breakdown:

• linux1804-64-asan: 8
• windows10-64: 5
• macosx1014-64-shippable: 54
• linux1804-64-shippable: 5
• windows7-32-shippable: 4
• linux1804-64: 3
• windows10-64-qr: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1630211&startday=2020-04-20&endday=2020-04-26&tree=all

Comment 15

[Andreea Pavel [:apavel]]

Jean-Yves, are the above fixed? no failures since yesterday.: https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2020-04-20&endday=2020-04-27&tree=trunk&bug=1630211

Comment 16

[Jean-Yves Avenard [:jya]]

(In reply to Andreea Pavel [:apavel] from comment #15)

Jean-Yves, are the above fixed? no failures since yesterday.: https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2020-04-20&endday=2020-04-27&tree=trunk&bug=1630211

the code has been disabled following the backout of bug 1632098.

So the issue is still there, just hidden for now.

Comment 17

[Jean-Yves Avenard [:jya]]

I fixed the error in the test, however in the terminal I see lots of errors such as:
5:42.33 GECKO(15376) JavaScript error: resource://gre/actors/PictureInPictureChild.jsm, line 332: TypeError: can't access property "addEventListener", this.contentWindow.windowRoot is null
5:42.36 INFO Console message: [JavaScript Error: "TypeError: can't access property "addEventListener", this.contentWindow.windowRoot is null" {file: "resource://gre/actors/PictureInPictureChild.jsm" line: 332}]

is this something you could look into?

Thanks.

Comment 18

[Jean-Yves Avenard [:jya]]

Attachment: Bug 1630211 - P1. Wait for page to load before closing it. r?mconley,gijs

BrowserTestUtils.closeWindow accesses the document before closing it in order to determine its type.

Ideally, we should probably modify BrowserTestUtils.domWindowOpened so that it only resolves the promise once loading has completed.

However, so far all consumer of BrowserTestUtils.domWindowOpened also wait for the load event right after.

Comment 19

[Jean-Yves Avenard [:jya]]

Attachment: Bug 1630211 - P3. Use new domWindowOpenedAndLoaded where we can. r?gijs

Remove duplicated code; and properly wait for the window to be loaded where needed.

Depends on D72792

Comment 20

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

(In reply to Jean-Yves Avenard [:jya] from comment #17)

is this something you could look into?

Filed bug 1633759 - hopefully I can get to it sooner rather than later!

Comment 21

[Jean-Yves Avenard [:jya]]

Attachment: Bug 1630211 - P2. Don't attempt to load data URI in the parent process. r?mconley,Gijs,mattwoodrow

This will cause an error and the load event won't be fired.

The test only needs to check that a window is opened on top, any content will do, so we use about:blank instead

Depends on D72792

Comment 22

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/cdf102e0ea37
P1. Wait for page to load before closing it. r=Gijs
https://hg.mozilla.org/integration/autoland/rev/26b1e4cb104e
P2. Don't attempt to load data URI in the parent process. r=Gijs
https://hg.mozilla.org/integration/autoland/rev/321cdd074741
P3. Use new domWindowOpenedAndLoaded where we can. r=Gijs

Comment 23

[Cosmin Sabou [:CosminS]]

https://hg.mozilla.org/mozilla-central/rev/cdf102e0ea37
https://hg.mozilla.org/mozilla-central/rev/26b1e4cb104e
https://hg.mozilla.org/mozilla-central/rev/321cdd074741