Intermittent devtools/client/debugger/test/mochitest/browser_dbg-console-link.js | Uncaught exception - waitFor - timed out after 500 tries.
Categories
(DevTools :: General, defect, P5)
Tracking
(Not tracked)
People
(Reporter: intermittent-bug-filer, Unassigned)
References
(Regression)
Details
(Keywords: intermittent-failure, regression, Whiteboard: [retriggered][stockwell fixed:backout])
Filed by: malexandru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=252151019&repo=autoland
Full log: https://queue.taskcluster.net/v1/task/T-LffsxPQ3aZDdcq4kIvJQ/runs/0/artifacts/public/logs/live_backing.log
07:53:47 INFO - TEST-START | devtools/client/debugger/test/mochitest/browser_dbg-console-link.js
07:53:47 INFO - GECKO(1736) | ++DOCSHELL 00A60800 == 2 [pid = 3312] [id = {2580edc7-bd36-479e-977d-d3252a027e41}]
07:53:47 INFO - GECKO(1736) | ++DOMWINDOW == 3 (112403A0) [pid = 3312] [serial = 47] [outer = 00000000]
07:53:47 INFO - GECKO(1736) | [Child 3312, Main Thread] WARNING: No active window: file z:/build/build/src/js/xpconnect/src/XPCJSContext.cpp, line 662
07:53:47 INFO - GECKO(1736) | [Child 3312, Main Thread] WARNING: No active window: file z:/build/build/src/js/xpconnect/src/XPCJSContext.cpp, line 662
07:53:47 INFO - GECKO(1736) | ++DOMWINDOW == 4 (00A67C00) [pid = 3312] [serial = 48] [outer = 112403A0]
07:53:47 INFO - GECKO(1736) | ++DOMWINDOW == 5 (12639800) [pid = 3312] [serial = 49] [outer = 112403A0]
07:53:47 INFO - GECKO(1736) | ++DOCSHELL 0DCF8400 == 9 [pid = 3168] [id = {5fc51e07-cb40-4201-bb26-8f6b5748c564}]
07:53:47 INFO - GECKO(1736) | ++DOMWINDOW == 24 (0E7AB940) [pid = 3168] [serial = 135] [outer = 00000000]
07:53:47 INFO - GECKO(1736) | ++DOMWINDOW == 25 (183DCC00) [pid = 3168] [serial = 136] [outer = 0E7AB940]
07:53:47 INFO - GECKO(1736) | ++DOMWINDOW == 26 (183D0000) [pid = 3168] [serial = 137] [outer = 0E7AB940]
07:53:47 INFO - GECKO(1736) | ++DOCSHELL 0087BC00 == 10 [pid = 3168] [id = {bdd819c4-b564-4791-b50d-9770f6811362}]
07:53:47 INFO - GECKO(1736) | ++DOMWINDOW == 27 (0E7AB820) [pid = 3168] [serial = 138] [outer = 00000000]
07:53:47 INFO - GECKO(1736) | ++DOMWINDOW == 28 (183D3C00) [pid = 3168] [serial = 139] [outer = 0E7AB820]
07:53:48 INFO - GECKO(1736) | [Parent 3168, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, nullptr) failed with result 0x804B000A: file z:/build/build/src/extensions/permissions/nsPermission.cpp, line 42
07:53:48 INFO - GECKO(1736) | [Parent 3168, Main Thread] WARNING: '!principal', file z:/build/build/src/netwerk/cookie/CookieSettings.cpp, line 131
07:53:48 INFO - GECKO(1736) | [Parent 3168, Main Thread] WARNING: 'NS_FAILED(rv)', file z:/build/build/src/toolkit/components/antitracking/StorageAccess.cpp, line 30
07:53:50 INFO - [660, Main Thread] WARNING: 'NS_FAILED(rv)', file z:/build/build/src/toolkit/xre/nsAppRunner.cpp, line 1148
07:53:54 INFO - TEST-INFO | started process screenshot
07:53:54 INFO - TEST-INFO | screenshot: exit 0
07:53:54 INFO - Buffered messages logged at 07:53:47
07:53:54 INFO - Entering test bound
07:53:54 INFO - Adding a new tab with URL: http://example.com/browser/devtools/client/debugger/test/mochitest/examples/doc-script-switching.html
07:53:54 INFO - Tab added and finished loading
07:53:54 INFO - Opening the toolbox
07:53:54 INFO - Buffered messages logged at 07:53:48
07:53:54 INFO - Toolbox opened and focused
07:53:54 INFO - Buffered messages finished
07:53:54 INFO - TEST-UNEXPECTED-FAIL | devtools/client/debugger/test/mochitest/browser_dbg-console-link.js | Uncaught exception - waitFor - timed out after 500 tries.
07:53:54 INFO - Leaving test bound
07:53:55 INFO - GECKO(1736) | --DOCSHELL 0A87F400 == 1 [pid = 1400] [id = {c59eceab-a7bb-4330-8824-6d1e3b351b73}] [url = http://example.com/browser/devtools/client/debugger/test/mochitest/examples/doc-scripts.html]
07:53:55 INFO - GECKO(1736) | --DOMWINDOW == 3 (08936CA0) [pid = 1400] [serial = 47] [outer = 00000000] [url = http://example.com/browser/devtools/client/debugger/test/mochitest/examples/doc-scripts.html]
07:53:55 INFO - GECKO(1736) | --DOCSHELL 112D0000 == 1 [pid = 3312] [id = {c1456d2b-8862-4286-981e-6643d1ecf64c}] [url = about:blank]
07:53:55 INFO - GECKO(1736) | --DOMWINDOW == 4 (11240CA0) [pid = 3312] [serial = 44] [outer = 00000000] [url = about:blank]
07:53:55 INFO - GECKO(1736) | --DOMWINDOW == 27 (183DCC00) [pid = 3168] [serial = 136] [outer = 00000000] [url = about:blank]
07:53:56 INFO - GECKO(1736) | [Parent 3168, Main Thread] WARNING: NS_ENSURE_TRUE(!mHasOrHasHadOwnerWindow || mOwnerWindow) failed: file z:/build/build/src/dom/events/DOMEventTargetHelper.cpp, line 318
07:53:56 INFO - GECKO(1736) | [Parent 3168, Main Thread] WARNING: NS_ENSURE_TRUE(!mHasOrHasHadOwnerWindow || mOwnerWindow) failed: file z:/build/build/src/dom/events/DOMEventTargetHelper.cpp, line 318
07:53:56 INFO - GECKO(1736) | [Parent 3168, Main Thread] WARNING: NS_ENSURE_TRUE(!mHasOrHasHadOwnerWindow || mOwnerWindow) failed: file z:/build/build/src/dom/events/DOMEventTargetHelper.cpp, line 318
07:53:56 INFO - GECKO(1736) | [Parent 3168, Main Thread] WARNING: NS_ENSURE_TRUE(!mHasOrHasHadOwnerWindow || mOwnerWindow) failed: file z:/build/build/src/dom/events/DOMEventTargetHelper.cpp, line 318
07:53:56 INFO - Removing tab.
07:53:56 INFO - Waiting for event: 'TabClose' on [object XULElement].
07:53:56 INFO - Got event: 'TabClose' on [object XULElement].
07:53:56 INFO - GECKO(1736) | [Child 1400, Main Thread] WARNING: No active window: file z:/build/build/src/js/xpconnect/src/XPCJSContext.cpp, line 662
07:53:56 INFO - Tab removed and finished closing
07:53:56 INFO - GECKO(1736) | --DOMWINDOW == 26 (0E7AB700) [pid = 3168] [serial = 131] [outer = 00000000] [url = chrome://devtools/content/debugger/index.html]
07:53:56 INFO - GECKO(1736) | --DOMWINDOW == 25 (0E7AB5E0) [pid = 3168] [serial = 128] [outer = 00000000] [url = about:devtools-toolbox]
07:53:56 INFO - GECKO(1736) | --DOMWINDOW == 24 (2A801B80) [pid = 3168] [serial = 133] [outer = 00000000] [url = chrome://devtools/content/webconsole/index.html]
07:53:56 INFO - GECKO(1736) | --DOCSHELL 2E0BD400 == 9 [pid = 3168] [id = {22d7cf6b-d874-4189-8a80-c19596fb622c}] [url = chrome://devtools/content/webconsole/index.html]
07:53:56 INFO - GECKO(1736) | --DOCSHELL 0DCF8400 == 8 [pid = 3168] [id = {5fc51e07-cb40-4201-bb26-8f6b5748c564}] [url = about:devtools-toolbox]
Comment 1•6 years ago
|
||
Looks like this bug together with Bug 1559761 started after these changes landed here: https://hg.mozilla.org/integration/autoland/rev/82daf65cbe5e55ddefa27e293dfcbfe27af23062
Retriggers: https://treeherder.mozilla.org/#/jobs?repo=autoland&searchStr=windows%2C7%2Cdebug%2Cmochitests%2Ctest-windows7-32%2Fdebug-mochitest-devtools-chrome-e10s-2%2Cm%28dt2%29&tochange=82daf65cbe5e55ddefa27e293dfcbfe27af23062&fromchange=7b70a9ccdc17a6b06662f7760334363493071017&group_state=expanded&selectedJob=252306430
Gabriele, could you please take a look over this? It has quite a high failures rate.
Comment 2•6 years ago
|
||
My change should does not affect tests directly but it's possible that it triggered issues that weren't visible before. The only direct effect of my change is that it sending memory-pressure
events when the appropriate conditions are met. Since memory-pressure
events trigger the garbage collector - among other things - I can speculate that it's causing a weakly-referenced object to be reclaimed (or something like that) which in turn causes the test to fail.
Comment 3•6 years ago
|
||
If I've read the test correctly this is checking that some lines in the console have been highlighted. The problem is that it's doing so via polling by spinning the event loop and the highlighting only lasts 200ms. So what's happening here is that a memory-pressure
event is sent during the test and it's slowing down the event loop making the check miss the narrow highlighting window.
Updated•6 years ago
|
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 8•6 years ago
|
||
Since this happens very frequently I suggest we disable this test until we can fix it. I believe it's possible to replace the polling in the test with a MutationObserver
so that it won't be timing-dependent anymore but I haven't had the time to do it yet.
Comment hidden (Intermittent Failures Robot) |
Comment 10•6 years ago
|
||
It seems that this isn't failing since the 25th: https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-06-21&endday=2019-06-28&tree=trunk&bug=1559760
It must've been solved by a patch that landed in that day.
Comment hidden (Intermittent Failures Robot) |
Updated•6 years ago
|
Comment hidden (Intermittent Failures Robot) |
Updated•6 years ago
|
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 15•6 years ago
•
|
||
In the last 7 days there were 91 failures associated with this bug: https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-07-05&endday=2019-07-12&tree=all&bug=1559760
Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=256156836&repo=autoland&lineNumber=9498
Occurs on windows7-32 debug build type.
Comment 16•6 years ago
|
||
Recent occurrences should be fixed by https://hg.mozilla.org/integration/autoland/rev/956e97b8354d666aa441eef42c21c88f2fbf775d
Comment hidden (Intermittent Failures Robot) |
Comment 18•6 years ago
|
||
Retrigger range for recent occurences https://treeherder.mozilla.org/#/jobs?repo=autoland&group_state=expanded&searchStr=windows%2C7%2Cdebug%2Cmochitests%2Ctest-windows7-32%2Fdebug-mochitest-devtools-chrome-e10s-5%2Cm%28dt5%29&tochange=b0eee59fb22c62f7afd987b65407506edb4b6f31&fromchange=c9f70b17e09affb7d2d28e31e6ea7427d1618905&selectedJob=259823773
Looks like this is coming from Bug 1534674, Daisuke will you please take a look?
Comment hidden (Intermittent Failures Robot) |
Comment 20•6 years ago
|
||
Hello, yes, I'll take a look.
Comment 21•6 years ago
|
||
Hello :apavel!
I took a look a bit though, I don't think the bug 1534674 caused this regression because this issue began from 2 month ago and the bug 1534674 was landed 7 days ago. What do you think?
Comment 22•6 years ago
|
||
Hi Daisuke, yes that is correct, however when your bug landed the failure rate increased that is why I believe it might be something from there.
Thank you for looking.
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 28•6 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.
Comment 29•5 years ago
|
||
This is still happening.
Recent failure: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=304239426&repo=autoland&lineNumber=3674
[task 2020-05-29T10:33:46.312Z] 10:33:46 INFO - TEST-START | devtools/client/debugger/test/mochitest/browser_dbg-console-link.js
[task 2020-05-29T10:33:52.883Z] 10:33:52 INFO - TEST-INFO | started process screentopng
[task 2020-05-29T10:33:53.064Z] 10:33:53 INFO - TEST-INFO | screentopng: exit 0
[task 2020-05-29T10:33:53.064Z] 10:33:53 INFO - Buffered messages logged at 10:33:46
[task 2020-05-29T10:33:53.064Z] 10:33:53 INFO - Entering test bound
[task 2020-05-29T10:33:53.065Z] 10:33:53 INFO - Adding a new tab with URL: http://example.com/browser/devtools/client/debugger/test/mochitest/examples/doc-script-switching.html
[task 2020-05-29T10:33:53.065Z] 10:33:53 INFO - Tab added and finished loading
[task 2020-05-29T10:33:53.065Z] 10:33:53 INFO - Opening the toolbox
[task 2020-05-29T10:33:53.065Z] 10:33:53 INFO - Console message: [JavaScript Error: "Content Security Policy: The page’s settings blocked the loading of a resource at inline (“default-src”)." {file: "chrome://global/content/elements/panel.js" line: 78}]
[task 2020-05-29T10:33:53.065Z] 10:33:53 INFO - Buffered messages logged at 10:33:47
[task 2020-05-29T10:33:53.065Z] 10:33:53 INFO - Console message: [JavaScript Error: "Content Security Policy: The page’s settings blocked the loading of a resource at inline (“default-src”)." {file: "chrome://global/content/elements/panel.js" line: 78}]
[task 2020-05-29T10:33:53.065Z] 10:33:53 INFO - Toolbox opened and focused
[task 2020-05-29T10:33:53.066Z] 10:33:53 INFO - Buffered messages finished
[task 2020-05-29T10:33:53.066Z] 10:33:53 INFO - TEST-UNEXPECTED-FAIL | devtools/client/debugger/test/mochitest/browser_dbg-console-link.js | Uncaught exception - waitFor - timed out after 500 tries.
[task 2020-05-29T10:33:53.066Z] 10:33:53 INFO - Leaving test bound
[task 2020-05-29T10:33:53.327Z] 10:33:53 INFO - Removing tab.
[task 2020-05-29T10:33:53.327Z] 10:33:53 INFO - Waiting for event: 'TabClose' on [object XULElement].
[task 2020-05-29T10:33:53.348Z] 10:33:53 INFO - Got event: 'TabClose' on [object XULElement].
[task 2020-05-29T10:33:53.351Z] 10:33:53 INFO - GECKO(1265) | console.warn: "IGNORED REDUX ACTION:" ({type:"AUTOCOMPLETE_CLEAR"})
[task 2020-05-29T10:33:53.366Z] 10:33:53 INFO - Tab removed and finished closing
[task 2020-05-29T10:33:53.394Z] 10:33:53 INFO - TEST-PASS | devtools/client/debugger/test/mochitest/browser_dbg-console-link.js | The main process DevToolsServer has no pending connection when the test ends -
[task 2020-05-29T10:33:53.419Z] 10:33:53 INFO - GECKO(1265) | MEMORY STAT | vsize 20976316MB | residentFast 1921MB
[task 2020-05-29T10:33:53.421Z] 10:33:53 INFO - TEST-OK | devtools/client/debugger/test/mochitest/browser_dbg-console-link.js | took 7095ms
Comment 30•5 years ago
|
||
Seems to be resurrected by the changes from bug 1637641.
Comment hidden (Intermittent Failures Robot) |
Comment 33•4 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.
Updated•4 years ago
|
Description
•