1668916 - Perma tier2 devtools/client/webconsole/test/browser/browser_jsterm_evaluation_context_selector_inspector.js | Test timed out -

Status: RESOLVED FIXED

(DevTools :: Console, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2020-10-02T17:10:03.950Z] 17:10:03     INFO - TEST-UNEXPECTED-FAIL | devtools/client/webconsole/test/browser/browser_jsterm_evaluation_context_selector_inspector.js | Test timed out - 
[task 2020-10-02T17:10:03.950Z] 17:10:03     INFO - GECKO(3087) | [Parent 3087, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /builds/worker/checkouts/gecko/layout/generic/nsFrameSelection.cpp, line 1598
[task 2020-10-02T17:10:05.686Z] 17:10:05     INFO - Removing tab.
[task 2020-10-02T17:10:05.686Z] 17:10:05     INFO - Waiting for event: 'TabClose' on [object XULElement].
[task 2020-10-02T17:10:05.714Z] 17:10:05     INFO - Got event: 'TabClose' on [object XULElement].
[task 2020-10-02T17:10:05.716Z] 17:10:05     INFO - GECKO(3087) | console.warn: "IGNORED REDUX ACTION:" "AUTOCOMPLETE_CLEAR"
[task 2020-10-02T17:10:05.744Z] 17:10:05     INFO - GECKO(3087) | [Parent 3087, Main Thread] WARNING: '!inner', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorProtocol.cpp, line 172
[task 2020-10-02T17:10:05.745Z] 17:10:05     INFO - GECKO(3087) | [Parent 3087, Main Thread] WARNING: '!inner', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorProtocol.cpp, line 172
[task 2020-10-02T17:10:05.752Z] 17:10:05     INFO - GECKO(3087) | [Parent 3087, Main Thread] WARNING: NS_ENSURE_TRUE(weakFrame.IsAlive()) failed: file /builds/worker/checkouts/gecko/layout/xul/nsXULPopupManager.cpp, line 1050
[task 2020-10-02T17:10:05.767Z] 17:10:05     INFO - Tab removed and finished closing
[task 2020-10-02T17:10:05.844Z] 17:10:05     INFO - GECKO(3087) | [Parent 3087: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fc62b30f400 == 8 [pid = 3087] [id = 183] [url = chrome://devtools/content/inspector/index.xhtml]
[task 2020-10-02T17:10:05.844Z] 17:10:05     INFO - GECKO(3087) | [Parent 3087: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fc632ddf400 == 7 [pid = 3087] [id = 184] [url = chrome://devtools/content/inspector/markup/markup.xhtml]
[task 2020-10-02T17:10:05.884Z] 17:10:05     INFO - TEST-PASS | devtools/client/webconsole/test/browser/browser_jsterm_evaluation_context_selector_inspector.js | The main process DevToolsServer has no pending connection when the test ends - 
[task 2020-10-02T17:10:05.900Z] 17:10:05     INFO - GECKO(3087) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-10-02T17:10:05.936Z] 17:10:05     INFO - GECKO(3087) | MEMORY STAT | vsize 3786MB | residentFast 518MB | heapAllocated 149MB
[task 2020-10-02T17:10:05.937Z] 17:10:05     INFO - TEST-OK | devtools/client/webconsole/test/browser/browser_jsterm_evaluation_context_selector_inspector.js | took 272643ms
[task 2020-10-02T17:10:05.974Z] 17:10:05     INFO - GECKO(3087) | [Child 3278: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 0x7f7c46be1000 == 1 [pid = 3278] [id = 59]
[task 2020-10-02T17:10:05.974Z] 17:10:05     INFO - GECKO(3087) | [Child 3278: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (0x7f7c64493180) [pid = 3278] [serial = 143] [outer = (nil)]
[task 2020-10-02T17:10:05.974Z] 17:10:05     INFO - GECKO(3087) | [Child 3278: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (0x7f7c46be2000) [pid = 3278] [serial = 144] [outer = 0x7f7c64493180]
[task 2020-10-02T17:10:06.118Z] 17:10:06     INFO - checking window state

Comment 1

[Julian Descottes [:jdescottes]]

I can reproduce the failure and I confirm it comes from Bug 1667084, in particular from the first patch https://hg.mozilla.org/integration/autoland/rev/9603a52d90c3 .

This patch made the evaluateExpression method in devtools/client/webconsole/actions/input.js slightly faster, and it seems that it prevents an eager evaluation.

In the test we click on "Use in Console" for two elements, in two different iframes running each in a separate process.
The first element will be assigned to temp0. But since they run in separate processes, the other element will also be assigned to temp0.
Normally this is all fine, temp0 should always be defined. However for the second iframe, the eager evaluation reads ReferenceError: temp0 is not defined

The problem is that we run into the following check (shortened):

    // Only re-evaluate if the expression did change.
    if (expression.trim() === terminalInput.trim()) {
      return null;
    }

https://searchfox.org/mozilla-central/rev/7ef5cefd0468b8f509efe38e0212de2398f4c8b3/devtools/client/webconsole/actions/input.js#311

This means that we skip eager evaluation if the text of the console input hasn't changed. And here we are unlucky because the text of the console remains temp0.

Why does the eager evaluation say ReferenceError: temp0 is not defined, instead of just showing the info from the first iframe?
This eager evaluation result comes from when we right clicked on the node from iframe2, which effectively switched the context of the toolbox to iframe2. At that point temp0 is not yet defined in the iframe2 process (it will only be defined when we click on "Use in Console"). This eager evaluation is "forced", meaning it will bypass the check mentioned above.

/**
 * Refresh the current eager evaluation by requesting a new eager evaluation.
 */
function updateInstantEvaluationResultForCurrentExpression() {
  return ({ getState, dispatch }) =>
    dispatch(terminalInputChanged(getState().history.terminalInput, true));
}

Before the patch, evaluateExpression was slower. DevTools had enough time to create the new temp0 variable before the eager evaluation hit the server. But this only works because the test immediately goes from right clicking on the node to clicking on "Use in console". A human trying to reproduce this will get the issue, even without the patch from Bug 1667084 (you can try on https://bug1659969-root.glitch.me/)

I am tempted to simply update the test here, in order to fix the permafail quickly. Our tree is orange enough these days. But we should come up with a better solution.

Comment 2

[Julian Descottes [:jdescottes]]

Attachment: Bug 1668916 - [devtools] Workaround for eager evaluation bug in browser_jsterm_evaluation_context_selector_inspector.js

Comment 3

[Intermittent Failures Robot]

16 failures in 4195 pushes (0.004 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 16

Platform breakdown:

• linux1804-64: 12
• windows10-64-shippable: 4

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1668916&startday=2020-09-28&endday=2020-10-04&tree=all

Comment 4

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/8cd889043de4
[devtools] Workaround for eager evaluation bug in browser_jsterm_evaluation_context_selector_inspector.js r=nchevobbe

Comment 5

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

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

Comment 6

[Raul Gurzau (:RaulG)]

https://hg.mozilla.org/mozilla-central/rev/8cd889043de4

Comment 7

[Intermittent Failures Robot]

2 failures in 4130 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 2

Platform breakdown:

• linux1804-64: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1668916&startday=2020-10-05&endday=2020-10-11&tree=all