Closed Bug 1630211 Opened 2 years ago Closed 2 years ago

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

Categories

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

defect

Tracking

()

RESOLVED FIXED
mozilla77
Tracking Status
firefox77 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: jya)

References

(Regression)

Details

(Keywords: intermittent-failure, Whiteboard: [retriggered])

Attachments

(3 files, 1 obsolete file)

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

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

Component: General → Video/Audio Controls
Regressed by: 1607984
Whiteboard: [retriggered]

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.

Flags: needinfo?(jyavenard)

(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.

Flags: needinfo?(jyavenard)

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

Assignee: nobody → jyavenard
Status: NEW → ASSIGNED
Regressed by: 1632098
No longer regressed by: 1607984

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

Summary: Intermittent 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 → 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
Duplicate of this bug: 1632898
Duplicate of this bug: 1632966
Attachment #9143334 - Attachment is obsolete: true

(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.

Flags: needinfo?(jyavenard)

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.

Flags: needinfo?(mconley)

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.

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

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

Depends on D72792

See Also: → 1633759

(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!

Flags: needinfo?(mconley)

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

Attachment #9144011 - Attachment description: Bug 1630211 - P2. Use new domWindowOpenedAndLoaded where we can. r?gijs → Bug 1630211 - P3. Use new domWindowOpenedAndLoaded where we can. r?gijs
Pushed by jyavenard@mozilla.com:
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
Status: ASSIGNED → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla77
You need to log in before you can comment on or make changes to this bug.