Open Bug 1586509 Opened 6 years ago Updated 3 years ago

Intermittent browser/components/extensions/test/browser/browser_ext_devtools_inspectedWindow.js | Test timed out -

Categories

(WebExtensions :: Untriaged, defect, P5)

defect

Tracking

(Not tracked)

REOPENED

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Blocks 1 open bug)

Details

(Keywords: intermittent-failure, regression)

Filed by: btara [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=269896916&repo=mozilla-central
Full log: https://queue.taskcluster.net/v1/task/PJppkHeuSHyrFODFzMsw8g/runs/0/artifacts/public/logs/live_backing.log


[task 2019-10-05T11:06:49.682Z] 11:06:49 INFO - TEST-START | browser/components/extensions/test/browser/browser_ext_devtools_inspectedWindow.js
[task 2019-10-05T11:07:34.705Z] 11:07:34 INFO - TEST-INFO | started process screenshot
[task 2019-10-05T11:07:34.774Z] 11:07:34 INFO - TEST-INFO | screenshot: exit 0
[task 2019-10-05T11:07:34.774Z] 11:07:34 INFO - Buffered messages logged at 11:06:49
[task 2019-10-05T11:07:34.774Z] 11:07:34 INFO - Entering test bound test_devtools_inspectedWindow_tabId
[task 2019-10-05T11:07:34.774Z] 11:07:34 INFO - Extension loaded
[task 2019-10-05T11:07:34.774Z] 11:07:34 INFO - Console message: Warning: attempting to write 10412 bytes to preference extensions.webextensions.uuids. This is bad for general performance and memory usage. Such an amount of data should rather be written to an external file. This preference will not be sent to any content processes.
[task 2019-10-05T11:07:34.774Z] 11:07:34 INFO - Buffered messages logged at 11:06:50
[task 2019-10-05T11:07:34.775Z] 11:07:34 INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_devtools_inspectedWindow.js | No devtools APIs should be available in the background page - Expected: undefined, Actual: undefined -
[task 2019-10-05T11:07:34.775Z] 11:07:34 INFO - Registering testBlankPanel tool to the developer tools
[task 2019-10-05T11:07:34.775Z] 11:07:34 INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_devtools_inspectedWindow.js | The runtime.getBackgroundPage API method should be missing in a devtools_page context - Expected: undefined, Actual: undefined -
[task 2019-10-05T11:07:34.775Z] 11:07:34 INFO - Developer toolbox opened on panel "testBlankPanel" for target {}
[task 2019-10-05T11:07:34.775Z] 11:07:34 INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_devtools_inspectedWindow.js | Got the expected tabId from devtool.inspectedWindow.tabId -
[task 2019-10-05T11:07:34.775Z] 11:07:34 INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_devtools_inspectedWindow.js | Got the expected tabId from devtool.inspectedWindow.tabId called in a devtool_page iframe -
[task 2019-10-05T11:07:34.775Z] 11:07:34 INFO - Developer toolbox closed for target {}
[task 2019-10-05T11:07:34.775Z] 11:07:34 INFO - Leaving test bound test_devtools_inspectedWindow_tabId
[task 2019-10-05T11:07:34.776Z] 11:07:34 INFO - Entering test bound test_devtools_inspectedWindow_eval
[task 2019-10-05T11:07:34.776Z] 11:07:34 INFO - Buffered messages logged at 11:06:51
[task 2019-10-05T11:07:34.776Z] 11:07:34 INFO - Extension loaded
[task 2019-10-05T11:07:34.776Z] 11:07:34 INFO - Console message: Warning: attempting to write 10492 bytes to preference extensions.webextensions.uuids. This is bad for general performance and memory usage. Such an amount of data should rather be written to an external file. This preference will not be sent to any content processes.
[task 2019-10-05T11:07:34.776Z] 11:07:34 INFO - Developer toolbox opened on panel "testBlankPanel" for target {}
[task 2019-10-05T11:07:34.776Z] 11:07:34 INFO - test inspectedWindow.eval with {"args":["window.location.href"],"expectedResults":{"evalResult":"http://mochi.test:8888/"}}
[task 2019-10-05T11:07:34.776Z] 11:07:34 INFO - Buffered messages finished
[task 2019-10-05T11:07:34.776Z] 11:07:34 INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/browser_ext_devtools_inspectedWindow.js | Test timed out -
[task 2019-10-05T11:07:34.781Z] 11:07:34 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-10-05T11:07:34.781Z] 11:07:34 INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/browser_ext_devtools_inspectedWindow.js | no tasks awaiting on messages - Got ["inspectedWindow-eval-result"], expected []
[task 2019-10-05T11:07:34.781Z] 11:07:34 INFO - Stack trace:
[task 2019-10-05T11:07:34.781Z] 11:07:34 INFO - chrome://mochikit/content/browser-test.js:test_is:1595
[task 2019-10-05T11:07:34.781Z] 11:07:34 INFO - chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:ExtensionTestUtils.loadExtension/<:31
[task 2019-10-05T11:07:34.781Z] 11:07:34 INFO - chrome://mochikit/content/browser-test.js:nextTest:860
[task 2019-10-05T11:07:34.781Z] 11:07:34 INFO - chrome://mochikit/content/browser-test.js:timeoutFn:1471
[task 2019-10-05T11:07:34.781Z] 11:07:34 INFO - setTimeout handlerchrome://mochikit/content/browser-test.js:Tester_execTest:1418
[task 2019-10-05T11:07:34.781Z] 11:07:34 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:1213
[task 2019-10-05T11:07:34.781Z] 11:07:34 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:805
[task 2019-10-05T11:07:34.782Z] 11:07:34 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-10-05T11:07:34.782Z] 11:07:34 INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/browser_ext_devtools_inspectedWindow.js | Extension left running at test shutdown -
[task 2019-10-05T11:07:34.782Z] 11:07:34 INFO - Stack trace:
[task 2019-10-05T11:07:34.782Z] 11:07:34 INFO - chrome://mochikit/content/browser-test.js:test_ok:1580
[task 2019-10-05T11:07:34.782Z] 11:07:34 INFO - chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:ExtensionTestUtils.loadExtension/<:109
[task 2019-10-05T11:07:34.782Z] 11:07:34 INFO - chrome://mochikit/content/browser-test.js:nextTest:860
[task 2019-10-05T11:07:34.782Z] 11:07:34 INFO - chrome://mochikit/content/browser-test.js:timeoutFn:1471
[task 2019-10-05T11:07:34.782Z] 11:07:34 INFO - setTimeout handler
chrome://mochikit/content/browser-test.js:Tester_execTest:1418
[task 2019-10-05T11:07:34.782Z] 11:07:34 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:1213
[task 2019-10-05T11:07:34.782Z] 11:07:34 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:805
[task 2019-10-05T11:07:34.873Z] 11:07:34 INFO - GECKO(10824) | MEMORY STAT | vsize 2104628MB | vsizeMaxContiguous 65447301MB | residentFast 433MB | heapAllocated 138MB
[task 2019-10-05T11:07:34.873Z] 11:07:34 INFO - TEST-OK | browser/components/extensions/test/browser/browser_ext_devtools_inspectedWindow.js | took 45197ms
[task 2019-10-05T11:07:34.873Z] 11:07:34 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-10-05T11:07:34.873Z] 11:07:34 INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/browser_ext_devtools_inspectedWindow.js | Found a tab after previous test timed out: http://mochi.test:8888/ -
[task 2019-10-05T11:07:34.915Z] 11:07:34 INFO - checking window state
[task 2019-10-05T11:07:35.159Z] 11:07:35 INFO - TEST-START | browser/components/extensions/test/browser/browser_ext_devtools_inspectedWindow_eval_bindings.js
[task 2019-10-05T11:07:36.100Z] 11:07:36 INFO - GECKO(10824) | console.log: "[DISPATCH] action type:" "CLEAR_FLEXBOX"
[task 2019-10-05T11:07:36.100Z] 11:07:36 INFO - GECKO(10824) | console.log: "[DISPATCH] action type:" "UPDATE_GRIDS"
[task 2019-10-05T11:07:36.125Z] 11:07:36 INFO - GECKO(10824) | console.log: "[DISPATCH] action type:" "UPDATE_OFFSET_PARENT"
[task 2019-10-05T11:07:36.135Z] 11:07:36 INFO - GECKO(10824) | console.log: "[DISPATCH] action type:" "UPDATE_LAYOUT"
[task 2019-10-05T11:07:36.153Z] 11:07:36 INFO - GECKO(10824) | console.log: "[DISPATCH] action type:" "CLEAR_FLEXBOX"
[task 2019-10-05T11:07:36.214Z] 11:07:36 INFO - GECKO(10824) | console.log: "[DISPATCH] action type:" "UPDATE_OFFSET_PARENT"
[task 2019-10-05T11:07:36.224Z] 11:07:36 INFO - GECKO(10824) | console.log: "[DISPATCH] action type:" "UPDATE_LAYOUT"
[task 2019-10-05T11:07:37.218Z] 11:07:37 INFO - GECKO(10824) | MEMORY STAT | vsize 2104631MB | vsizeMaxContiguous 65447301MB | residentFast 446MB | heapAllocated 167MB
[task 2019-10-05T11:07:37.218Z] 11:07:37 INFO - TEST-OK | browser/components/extensions/test/browser/browser_ext_devtools_inspectedWindow_eval_bindings.js | took 2064ms

Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 6 years ago6 years ago
Resolution: --- → INCOMPLETE

There are 20 total failures in the last 7 days.

debug: windows10-64, windows10-64-qr, linux1804-64, windows7-32
opt: windows10-64-shippable, macosx1014-64-shippable, windows7-32-shippable
asan: windows10-64

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=300136641&repo=autoland&lineNumber=15731

Flags: needinfo?(mixedpuppy)

Seems we had a blip for a couple weeks, then back to normal, but ni? luca incase he sees something obvious.

Flags: needinfo?(mixedpuppy) → needinfo?(lgreco)

(In reply to Shane Caraveo (:mixedpuppy) (on PTO) from comment #18)

Seems we had a blip for a couple weeks, then back to normal, but ni? luca incase he sees something obvious.

I looked to the last failures available and I can't see anything useful in the failure logs, the test was calling browser.devtools.inspectedWindow.eval and it did fail for timeout while waiting for the "inspectedWindow-eval-result" message, but then it seems that we got that message when the test was exiting due to the timeout failure:

[task 2020-06-09T20:36:09.359Z] 20:36:09     INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/browser_ext_devtools_inspectedWindow.js | Test timed out - 
[task 2020-06-09T20:36:09.359Z] 20:36:09     INFO - GECKO(1252) | [Parent 1252: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 0x7fefaa43f400 == 8 [pid = 1252] [id = {cb96b6be-2228-48dd-aec7-5fda7f23095d}]
[task 2020-06-09T20:36:09.359Z] 20:36:09     INFO - GECKO(1252) | [Parent 1252: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 15 (0x7fefadca9de0) [pid = 1252] [serial = 163] [outer = (nil)]
[task 2020-06-09T20:36:09.360Z] 20:36:09     INFO - GECKO(1252) | [Parent 1252: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 16 (0x7fefaa446000) [pid = 1252] [serial = 164] [outer = 0x7fefadca9de0]
[task 2020-06-09T20:36:09.421Z] 20:36:09     INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-06-09T20:36:09.422Z] 20:36:09     INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/browser_ext_devtools_inspectedWindow.js | no tasks awaiting on messages - Got ["inspectedWindow-eval-result"], expected []

It may have been related to some changes happened on the devtools side (maybe some of the fission-related changes) that may have started to trigger the intermittent failure, and then some additional changes may have fixed it.

Unfortunately I can't currently see any other detail in the failure logs that would help me to identify exactly what changes may have introduced and then fixed the higher intermittency.

Flags: needinfo?(lgreco)
Severity: normal → S3
Severity: normal → S3
You need to log in before you can comment on or make changes to this bug.