Closed Bug 1559760 Opened 6 years ago Closed 4 years ago

Intermittent devtools/client/debugger/test/mochitest/browser_dbg-console-link.js | Uncaught exception - waitFor - timed out after 500 tries.

Categories

(DevTools :: General, defect, P5)

defect

Tracking

(Not tracked)

RESOLVED INCOMPLETE

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]

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.

Flags: needinfo?(gsvelto)

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.

Whiteboard: [retriggered]

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.

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.

Whiteboard: [retriggered][stockwell disable-recommended] → [retriggered]
Whiteboard: [retriggered][stockwell disable-recommended] → [retriggered][stockwell unknown]
Whiteboard: [retriggered][stockwell disable-recommended] → [retriggered][stockwell unknown]
Regressed by: 1561092
Whiteboard: [retriggered][stockwell disable-recommended] → [retriggered][stockwell fixed:backout]

Hello, yes, I'll take a look.

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?

Flags: needinfo?(daisuke) → needinfo?(apavel)

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.

Flags: needinfo?(apavel)
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → INCOMPLETE

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
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

Seems to be resurrected by the changes from bug 1637641.

Flags: needinfo?(daisuke)

Low frequency, clearing the ni

Flags: needinfo?(daisuke)
Status: REOPENED → RESOLVED
Closed: 6 years ago4 years ago
Resolution: --- → INCOMPLETE
Has Regression Range: --- → yes
You need to log in before you can comment on or make changes to this bug.