1655951 - Perma [tier2] devtools/client/webconsole/test/browser/browser_jsterm_evaluation_context_selector_pause_in_debugger.js | Test timed out -

Status: RESOLVED FIXED

(DevTools :: Console, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: apavel [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=311377034&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/XlBSy_mwT46ngDEO-4hVlA/runs/0/artifacts/public/logs/live_backing.log

---

[task 2020-07-29T11:07:16.561Z] 11:07:16 INFO - TEST-START | devtools/client/webconsole/test/browser/browser_jsterm_evaluation_context_selector_pause_in_debugger.js
[task 2020-07-29T11:07:16.824Z] 11:07:16 INFO - GECKO(2798) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpx1idgJ.mozrunner/runtests_leaks_tab_pid3619.log
[task 2020-07-29T11:07:16.824Z] 11:07:16 INFO - GECKO(2798) | [3619, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp, line 246
[task 2020-07-29T11:07:17.123Z] 11:07:17 INFO - GECKO(2798) | [Child 3565: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7f2a53ecd800 == 0 [pid = 3565] [id = {ccc9c22f-f0b6-49bf-bf01-f3ac9102c09b}] [url = http://example.org/browser/devtools/client/webconsole/test/browser/test-console-evaluation-context-selector-child.html?id=iframe-1]
[task 2020-07-29T11:07:17.143Z] 11:07:17 INFO - GECKO(2798) | [Child 3619, Main Thread] WARNING: could not set real-time limit in CubebUtils::InitLibrary: file /builds/worker/checkouts/gecko/dom/media/CubebUtils.cpp, line 626
[task 2020-07-29T11:07:17.179Z] 11:07:17 INFO - GECKO(2798) | [Parent 2798: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7f1364ab3400 == 9 [pid = 2798] [id = {541df792-c0d3-43ec-beb5-f814b6541c9e}] [url = chrome://devtools/content/inspector/markup/markup.xhtml]
[task 2020-07-29T11:07:17.180Z] 11:07:17 INFO - GECKO(2798) | [Parent 2798: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7f1364832000 == 8 [pid = 2798] [id = {9b68ef49-5b9b-497f-a96a-0d220b85ba2d}] [url = chrome://devtools/content/inspector/index.xhtml]
[task 2020-07-29T11:07:17.180Z] 11:07:17 INFO - GECKO(2798) | [Child 3538: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7f2a529c3c00 == 0 [pid = 3538] [id = {7835d2cb-9046-4ce0-a968-56f120593438}] [url = http://example.com/browser/devtools/client/webconsole/test/browser/test-console-evaluation-context-selector.html]
[task 2020-07-29T11:07:17.187Z] 11:07:17 INFO - GECKO(2798) | [Child 3567: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7f52446cf800 == 0 [pid = 3567] [id = {e1ce7b73-f06b-4366-b110-e4239b1d53de}] [url = http://mochi.test:8888/browser/devtools/client/webconsole/test/browser/test-console-evaluation-context-selector-child.html?id=iframe-2]
[task 2020-07-29T11:07:17.511Z] 11:07:17 INFO - GECKO(2798) | [Child 3565: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (0x7f2a702936f0) [pid = 3565] [serial = 1] [outer = (nil)] [url = http://example.org/browser/devtools/client/webconsole/test/browser/test-console-evaluation-context-selector-child.html?id=iframe-1]
[task 2020-07-29T11:07:17.514Z] 11:07:17 INFO - GECKO(2798) | [Child 3565: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 0 (0x7f2a5a251400) [pid = 3565] [serial = 3] [outer = (nil)] [url = http://example.org/browser/devtools/client/webconsole/test/browser/test-console-evaluation-context-selector-child.html?id=iframe-1]
[task 2020-07-29T11:07:17.577Z] 11:07:17 INFO - GECKO(2798) | [Child 3567: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (0x7f5244650400) [pid = 3567] [serial = 2] [outer = (nil)] [url = about:blank]
[task 2020-07-29T11:07:17.577Z] 11:07:17 INFO - GECKO(2798) | [Child 3567: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (0x7f5260a936f0) [pid = 3567] [serial = 1] [outer = (nil)] [url = http://mochi.test:8888/browser/devtools/client/webconsole/test/browser/test-console-evaluation-context-selector-child.html?id=iframe-2]
[task 2020-07-29T11:07:17.577Z] 11:07:17 INFO - GECKO(2798) | [Child 3567: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 0 (0x7f5244c2d400) [pid = 3567] [serial = 3] [outer = (nil)] [url = http://mochi.test:8888/browser/devtools/client/webconsole/test/browser/test-console-evaluation-context-selector-child.html?id=iframe-2]
[task 2020-07-29T11:07:17.581Z] 11:07:17 INFO - GECKO(2798) | [Child 3565, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp, line 3359
[task 2020-07-29T11:07:17.597Z] 11:07:17 INFO - GECKO(2798) | [Child 3538: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (0x7f2a6ed936f0) [pid = 3538] [serial = 1] [outer = (nil)] [url = http://example.com/browser/devtools/client/webconsole/test/browser/test-console-evaluation-context-selector.html]
[task 2020-07-29T11:07:17.600Z] 11:07:17 INFO - GECKO(2798) | [Child 3538: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 0 (0x7f2a58d4a400) [pid = 3538] [serial = 3] [outer = (nil)] [url = http://example.com/browser/devtools/client/webconsole/test/browser/test-console-evaluation-context-selector.html]
[task 2020-07-29T11:07:17.628Z] 11:07:17 INFO - GECKO(2798) | [Child 3567, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp, line 3359
[task 2020-07-29T11:07:17.644Z] 11:07:17 INFO - GECKO(2798) | [Child 3565, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp, line 4343
[task 2020-07-29T11:07:17.660Z] 11:07:17 INFO - GECKO(2798) | [Child 3538, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp, line 3359
[task 2020-07-29T11:07:17.667Z] 11:07:17 INFO - GECKO(2798) | [Child 3567, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp, line 4343
[task 2020-07-29T11:07:17.703Z] 11:07:17 INFO - GECKO(2798) | [Child 3538, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp, line 4343
[task 2020-07-29T11:07:17.738Z] 11:07:17 INFO - GECKO(2798) | [Child 3619: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 0x7ff9e8cbdc00 == 1 [pid = 3619] [id = {150fcfd2-eff5-455c-8fbe-234ecbed0412}]
[task 2020-07-29T11:07:17.754Z] 11:07:17 INFO - GECKO(2798) | [Child 3619: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (0x7ffa050936f0) [pid = 3619] [serial = 1] [outer = (nil)]
[task 2020-07-29T11:07:17.754Z] 11:07:17 INFO - GECKO(2798) | [Child 3619: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (0x7ff9e98a0400) [pid = 3619] [serial = 2] [outer = 0x7ffa050936f0]
[task 2020-07-29T11:07:17.842Z] 11:07:17 INFO - GECKO(2798) | [Child 3619, Main Thread] WARNING: NS_ENSURE_TRUE(info) failed: file /builds/worker/checkouts/gecko/extensions/permissions/PermissionDelegateHandler.cpp, line 351
[task 2020-07-29T11:07:17.843Z] 11:07:17 INFO - GECKO(2798) | [Child 3619: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 3 (0x7ff9ef047400) [pid = 3619] [serial = 3] [outer = 0x7ffa050936f0]
[task 2020-07-29T11:07:17.995Z] 11:07:17 INFO - GECKO(2798) | [Child 3619: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 0x7ff9e989e800 == 2 [pid = 3619] [id = {db3b251d-7abe-414e-a91c-43d328d5360a}]
[task 2020-07-29T11:07:17.995Z] 11:07:17 INFO - GECKO(2798) | [Child 3619: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 4 (0x7ffa05093350) [pid = 3619] [serial = 4] [outer = (nil)]
[task 2020-07-29T11:07:18.010Z] 11:07:18 INFO - GECKO(2798) | [Child 3619: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 5 (0x7ff9e98a2800) [pid = 3619] [serial = 5] [outer = 0x7ffa05093350]
[task 2020-07-29T11:07:18.126Z] 11:07:18 INFO - GECKO(2798) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpx1idgJ.mozrunner/runtests_leaks_tab_pid3646.log

[task 2020-07-29T11:10:17.197Z] 11:10:17 INFO - TEST-PASS | devtools/client/webconsole/test/browser/browser_jsterm_evaluation_context_selector_pause_in_debugger.js | The context was set to the second iframe document -
[task 2020-07-29T11:10:17.197Z] 11:10:17 INFO - TEST-PASS | devtools/client/webconsole/test/browser/browser_jsterm_evaluation_context_selector_pause_in_debugger.js | Got eager evaluation result /mochi.test/ -
[task 2020-07-29T11:10:17.198Z] 11:10:17 INFO - TEST-PASS | devtools/client/webconsole/test/browser/browser_jsterm_evaluation_context_selector_pause_in_debugger.js | Instant evaluation has the expected result -
[task 2020-07-29T11:10:17.199Z] 11:10:17 INFO - Buffered messages logged at 11:08:38
[task 2020-07-29T11:10:17.203Z] 11:10:17 INFO - Console message: [JavaScript Error: "1596020918598 addons.xpi ERROR System addon update list error Error: got node name: html, expected: updates" {file: "resource://gre/modules/Log.jsm" line: 723}]
[task 2020-07-29T11:10:17.204Z] 11:10:17 INFO - append@resource://gre/modules/Log.jsm:723:12
[task 2020-07-29T11:10:17.205Z] 11:10:17 INFO - log@resource://gre/modules/Log.jsm:379:16
[task 2020-07-29T11:10:17.206Z] 11:10:17 INFO - error@resource://gre/modules/Log.jsm:387:10
[task 2020-07-29T11:10:17.206Z] 11:10:17 INFO - updateSystemAddons/res<@resource://gre/modules/addons/XPIInstall.jsm:3979:25
[task 2020-07-29T11:10:17.207Z] 11:10:17 INFO - promise callbackupdateSystemAddons@resource://gre/modules/addons/XPIInstall.jsm:3979:7
[task 2020-07-29T11:10:17.207Z] 11:10:17 INFO - asyncXPIProvider[meth]@resource://gre/modules/addons/XPIProvider.jsm:3188:28
[task 2020-07-29T11:10:17.208Z] 11:10:17 INFO - backgroundUpdateCheck/buPromise<@resource://gre/modules/AddonManager.jsm:1373:13
[task 2020-07-29T11:10:17.209Z] 11:10:17 INFO - backgroundUpdateCheck@resource://gre/modules/AddonManager.jsm:1381:7
[task 2020-07-29T11:10:17.209Z] 11:10:17 INFO - backgroundUpdateTimerHandler@resource://gre/modules/AddonManager.jsm:3505:26
[task 2020-07-29T11:10:17.210Z] 11:10:17 INFO - notify@resource://gre/modules/addonManager.js:174:25
[task 2020-07-29T11:10:17.210Z] 11:10:17 INFO - TM_notify/<@resource://gre/modules/UpdateTimerManager.jsm:221:50
[task 2020-07-29T11:10:17.211Z] 11:10:17 INFO - TM_notify@resource://gre/modules/UpdateTimerManager.jsm:292:7
[task 2020-07-29T11:10:17.211Z] 11:10:17 INFO -
[task 2020-07-29T11:10:17.212Z] 11:10:17 INFO - Buffered messages finished
[task 2020-07-29T11:10:17.212Z] 11:10:17 INFO - TEST-UNEXPECTED-FAIL | devtools/client/webconsole/test/browser/browser_jsterm_evaluation_context_selector_pause_in_debugger.js | Test timed out -
[task 2020-07-29T11:10:17.213Z] 11:10:17 INFO - GECKO(2798) | [Parent 2798, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /builds/worker/checkouts/gecko/layout/generic/nsFrameSelection.cpp, line 1605
[task 2020-07-29T11:10:18.703Z] 11:10:18 INFO - Removing tab.
[task 2020-07-29T11:10:18.704Z] 11:10:18 INFO - Waiting for event: 'TabClose' on [object XULElement].
[task 2020-07-29T11:10:18.732Z] 11:10:18 INFO - Got event: 'TabClose' on [object XULElement].
[task 2020-07-29T11:10:18.757Z] 11:10:18 INFO - GECKO(2798) | [Parent 2798, Main Thread] WARNING: '!inner', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorProtocol.cpp, line 172
[task 2020-07-29T11:10:18.758Z] 11:10:18 INFO - GECKO(2798) | [Parent 2798, Main Thread] WARNING: '!inner', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorProtocol.cpp, line 172
[task 2020-07-29T11:10:18.766Z] 11:10:18 INFO - GECKO(2798) | JavaScript error: , line 0: AbortError: Actor 'SpecialPowers' destroyed before query 'Spawn' was resolved
[task 2020-07-29T11:10:18.783Z] 11:10:18 INFO - Tab removed and finished closing
[task 2020-07-29T11:10:18.818Z] 11:10:18 INFO - GECKO(2798) | JavaScript error: , line 0: NotFoundError: No such JSWindowActor 'DevToolsFrame'
[task 2020-07-29T11:10:18.826Z] 11:10:18 INFO - GECKO(2798) | [Parent 2798: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7f135f9c5800 == 7 [pid = 2798] [id = {1aa05f0c-0f0d-4ff2-a303-e44a8df53821}] [url = chrome://devtools/content/debugger/index.html]
[task 2020-07-29T11:10:18.863Z] 11:10:18 INFO - Console message: [JavaScript Error: "NotFoundError: No such JSWindowActor 'DevToolsFrame'"]
[task 2020-07-29T11:10:18.863Z] 11:10:18 INFO - TEST-PASS | devtools/client/webconsole/test/browser/browser_jsterm_evaluation_context_selector_pause_in_debugger.js | The main process DevToolsServer has no pending connection when the test ends -
[task 2020-07-29T11:10:18.867Z] 11:10:18 INFO - Console message: [JavaScript Error: "AbortError: Actor 'SpecialPowers' destroyed before query 'Spawn' was resolved"]
[task 2020-07-29T11:10:18.888Z] 11:10:18 INFO - GECKO(2798) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-07-29T11:10:18.895Z] 11:10:18 INFO - GECKO(2798) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-07-29T11:10:18.951Z] 11:10:18 INFO - GECKO(2798) | MEMORY STAT | vsize 3701MB | residentFast 452MB | heapAllocated 136MB
[task 2020-07-29T11:10:18.951Z] 11:10:18 INFO - TEST-OK | devtools/client/webconsole/test/browser/browser_jsterm_evaluation_context_selector_pause_in_debugger.js | took 182394ms
[task 2020-07-29T11:10:18.987Z] 11:10:18 INFO - GECKO(2798) | [Child 2979: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 0x7fb54dc94400 == 1 [pid = 2979] [id = {daf2bb96-b6a1-4632-880b-f127b86a1e63}]
[task 2020-07-29T11:10:18.987Z] 11:10:18 INFO - GECKO(2798) | [Child 2979: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (0x7fb569e93350) [pid = 2979] [serial = 181] [outer = (nil)]
[task 2020-07-29T11:10:18.990Z] 11:10:18 INFO - GECKO(2798) | [Child 2979: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (0x7fb54dc95400) [pid = 2979] [serial = 182] [outer = 0x7fb569e93350]
[task 2020-07-29T11:10:19.152Z] 11:10:19 INFO - checking window state
[task 2020-07-29T11:10:19.156Z] 11:10:19 INFO - GECKO(2798) | [Child 2979: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 3 (0x7fb54e00d400) [pid = 2979] [serial = 183] [outer = 0x7fb569e93350]

Comment 1

[Intermittent Failures Robot]

39 failures in 846 pushes (0.046 failures/push) were associated with this bug yesterday.

Repository breakdown:

• mozilla-central: 18
• try: 21

Platform breakdown:

• linux1804-64: 10
• windows10-64-shippable: 7
• linux1804-64-shippable: 5
• linux1804-64-qr: 3
• windows10-64-qr: 1
• windows10-64: 4
• windows7-32: 3
• macosx1014-64: 4
• macosx1014-64-qr: 2

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

Comment 2

[Nicolas Chevobbe [:nchevobbe]]

for some reason the focus don't seem to be on the input when we try to hit Enter, so the test times out. I think I have a fix

Comment 3

[Nicolas Chevobbe [:nchevobbe]]

Attachment: Bug 1655951 - Fix browser/browser_jsterm_evaluation_context_selector_pause_in_debugger.js failure. r=jdescottes.

It seems that the test was failing because the focus wasn't on the console by
the time we were trying to evaluate the input, so the Enter keypress wasn't
registered and the input not evaluated.
This is fixed by focusing the console input in keyboardExecuteAndWaitForMessage,
before hitting Enter.

Comment 4

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/67b75e52a7a2
Fix browser/browser_jsterm_evaluation_context_selector_pause_in_debugger.js failure. r=jdescottes.

Comment 5

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

https://hg.mozilla.org/mozilla-central/rev/67b75e52a7a2

Comment 6

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

Set release status flags based on info from the regressing bug 1633727

Comment 7

[Intermittent Failures Robot]

46 failures in 4289 pushes (0.011 failures/push) were associated with this bug in the last 7 days.

This is the #25 most frequent failure this week.

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

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

Repository breakdown:

• mozilla-central: 25
• try: 21

Platform breakdown:

• linux1804-64: 12
• windows10-64-shippable: 10
• linux1804-64-shippable: 7
• linux1804-64-qr: 3
• windows10-64-qr: 1
• windows10-64: 4
• windows7-32: 3
• macosx1014-64: 4
• macosx1014-64-qr: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1655951&startday=2020-07-27&endday=2020-08-02&tree=all