Open Bug 1591590 Opened 5 years ago Updated 3 days ago

Intermittent devtools/client/webconsole/test/browser/browser_toolbox_console_new_process.js | single tracking bug

Categories

(DevTools :: Console, defect, P5)

Product:
DevTools
Component:
Console
Type:
defect

Tracking

(Not tracked)

Status:
ASSIGNED

People

(Reporter: intermittent-bug-filer, Assigned: nchevobbe)

References

(Regression)

Details

(5 keywords, Whiteboard: [retriggered][stockwell disabled][stockwell unknown])

Attachments

(5 files, 1 obsolete file)

Bug 1591590 - Disable browser_toolbox_console_new_process.js on macos debug, linux debug and windows ccov for frequent failures. r=nchevobbe
47 bytes, text/x-phabricator-request
Details | Review
Bug 1591590 - Disable browser_toolbox_console_new_process.js also on Linux ccov. r=nchevobbe DONTBUILD
47 bytes, text/x-phabricator-request
Details | Review
image.png
70.01 KB, image/png
Details
Bug 1591590 Disable browser_toolbox_console_new_process.js on win debug r=nchevobbe
47 bytes, text/x-phabricator-request
Details | Review
Bug 1591590 - disabale browser_toolbox_console_new_process.js on Win_64_opt for frequent failures. r=#intermittent-reviewers
48 bytes, text/x-phabricator-request
Details | Review

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

[task 2019-10-25T19:07:58.751Z] 19:07:58 INFO - TEST-START | devtools/client/webconsole/test/browser/browser_toolbox_console_new_process.js
[task 2019-10-25T19:13:58.944Z] 19:13:58 INFO - Buffered messages logged at 19:09:04
[task 2019-10-25T19:13:58.944Z] 19:13:58 INFO - Console message: [JavaScript Warning: "Use of nsIFile in content process is deprecated." {file: "resource://gre/modules/NetUtil.jsm" line: 253}]
[task 2019-10-25T19:13:58.944Z] 19:13:58 INFO - Console message: [JavaScript Warning: "Use of nsIFile in content process is deprecated." {file: "resource://gre/modules/NetUtil.jsm" line: 253}]
[task 2019-10-25T19:13:58.944Z] 19:13:58 INFO - Console message: [JavaScript Warning: "Use of nsIFile in content process is deprecated." {file: "resource://gre/modules/NetUtil.jsm" line: 253}]
[task 2019-10-25T19:13:58.944Z] 19:13:58 INFO - Console message: [JavaScript Warning: "Use of nsIFile in content process is deprecated." {file: "resource://gre/modules/NetUtil.jsm" line: 253}]
[task 2019-10-25T19:13:58.945Z] 19:13:58 INFO - Buffered messages logged at 19:09:28
[task 2019-10-25T19:13:58.945Z] 19:13:58 INFO - Longer timeout required, waiting longer... Remaining timeouts: 3
[task 2019-10-25T19:13:58.945Z] 19:13:58 INFO - Buffered messages logged at 19:10:58
[task 2019-10-25T19:13:58.945Z] 19:13:58 INFO - Longer timeout required, waiting longer... Remaining timeouts: 2
[task 2019-10-25T19:13:58.945Z] 19:13:58 INFO - Buffered messages logged at 19:12:28
[task 2019-10-25T19:13:58.945Z] 19:13:58 INFO - Longer timeout required, waiting longer... Remaining timeouts: 1
[task 2019-10-25T19:13:58.945Z] 19:13:58 INFO - Buffered messages finished
[task 2019-10-25T19:13:58.945Z] 19:13:58 INFO - TEST-UNEXPECTED-FAIL | devtools/client/webconsole/test/browser/browser_toolbox_console_new_process.js | Test timed out -
[task 2019-10-25T19:13:58.946Z] 19:13:58 INFO - Removing tab.
[task 2019-10-25T19:13:58.946Z] 19:13:58 INFO - Waiting for event: 'TabClose' on [object XULElement].
[task 2019-10-25T19:13:58.967Z] 19:13:58 INFO - Got event: 'TabClose' on [object XULElement].
[task 2019-10-25T19:13:59.007Z] 19:13:59 INFO - Tab removed and finished closing
[task 2019-10-25T19:13:59.007Z] 19:13:59 INFO - GECKO(10192) | [Parent 6976, Main Thread] WARNING: NS_ENSURE_TRUE(!mInput.IsReferenced()) failed: file z:/build/build/src/netwerk/base/nsSocketTransport2.cpp, line 2501
[task 2019-10-25T19:13:59.087Z] 19:13:59 INFO - TEST-PASS | devtools/client/webconsole/test/browser/browser_toolbox_console_new_process.js | The main process DebuggerServer has no pending connection when the test ends -
[task 2019-10-25T19:13:59.188Z] 19:13:59 INFO - GECKO(10192) | MEMORY STAT | vsize 2104984MB | vsizeMaxContiguous 65455724MB | residentFast 673MB | heapAllocated 247MB
[task 2019-10-25T19:13:59.188Z] 19:13:59 INFO - TEST-OK | devtools/client/webconsole/test/browser/browser_toolbox_console_new_process.js | took 360442ms
[task 2019-10-25T19:13:59.207Z] 19:13:59 INFO - GECKO(10192) | ++DOCSHELL 0000020186585000 == 2 [pid = 2508] [id = {4daadceb-e147-4ab8-8ea1-6979ff5ec884}]
[task 2019-10-25T19:13:59.207Z] 19:13:59 INFO - GECKO(10192) | ++DOMWINDOW == 3 (000002018BB2F980) [pid = 2508] [serial = 223] [outer = 0000000000000000]
[task 2019-10-25T19:13:59.207Z] 19:13:59 INFO - GECKO(10192) | ++DOMWINDOW == 4 (000002018A89A000) [pid = 2508] [serial = 224] [outer = 000002018BB2F980]
[task 2019-10-25T19:13:59.306Z] 19:13:59 INFO - checking window state
[task 2019-10-25T19:13:59.306Z] 19:13:59 INFO - GECKO(10192) | must wait for focus

Whiteboard: [retriggered]
Flags: needinfo?(nchevobbe)

Nicolas any updates here?

Flags: needinfo?(nchevobbe)
Whiteboard: [retriggered] → [retriggered][stockwell needswork:owner]

Sorry I was off for a few days. Looking at it now

Flags: needinfo?(nchevobbe)

Here's a failure that happens on the test:

 console.log: "Request to connect to ProcessDescriptor "1678" failed: 
  Error: 
    Connection closed, pending request to server1.conn0.processDescriptor1024, type getTarget failed
    Request stack:
      request@resource://devtools/shared/protocol/Front.js:232:14
      generateRequestMethods/</frontProto[name]@resource://devtools/shared/protocol/Front/FrontClassWithSpec.js:49:19
      getTarget/this._targetFrontPromise<@resource://devtools/shared/fronts/descriptors/process.js:70:40
      getTarget@resource://devtools/shared/fronts/descriptors/process.js:87:7
      updateProcessTargets/targets<@resource://devtools/client/debugger/src/client/firefox/targets.js:91:119
      updateProcessTargets@resource://devtools/client/debugger/src/client/firefox/targets.js:91:90
      async*updateTargets@resource://devtools/client/debugger/src/client/firefox/targets.js:99:11
      updateThreads@resource://devtools/client/debugger/src/client/firefox/commands.js:458:36
      fetchThreads@resource://devtools/client/debugger/src/client/firefox/commands.js:448:10
      updateThreads/<@resource://devtools/client/debugger/src/actions/threads.js:23:34
      thunk/</</<@resource://devtools/client/debugger/src/actions/utils/middleware/thunk.js:29:45
      bindActionCreator/<@resource://devtools/client/shared/vendor/redux.js:644:12
      threadListChanged@resource://devtools/client/debugger/src/client/firefox/events.js:106:11
      setupEvents/<@resource://devtools/client/debugger/src/client/firefox/events.js:42:75
      emit@resource://devtools/shared/event-emitter.js:190:24
      emit@resource://devtools/shared/event-emitter.js:271:18
      onPacket@resource://devtools/shared/protocol/Front.js:270:13
      onPacket@resource://devtools/shared/client/debugger-client.js:583:13
      _onJSONObjectReady/<@resource://devtools/shared/transport/transport.js:464:22
      exports.makeInfallible/<@resource://devtools/shared/ThreadSafeDevToolsUtils.js:111:22
      DevToolsUtils.executeSoon*exports.executeSoon@resource://devtools/shared/DevToolsUtils.js:62:21
      _onJSONObjectReady@resource://devtools/shared/transport/transport.js:460:19
      JSONPacket.prototype.read@resource://devtools/shared/transport/packets.js:187:19
      _processIncoming@resource://devtools/shared/transport/transport.js:386:24
      DebuggerTransport.prototype.onInputStreamReady<@resource://devtools/shared/transport/transport.js:332:14
      exports.makeInfallible/<@resource://devtools/shared/ThreadSafeDevToolsUtils.js:111:22

So the debugger detects a change in threads (threadListChanged) and try to get a target from a descriptor while the connection is being closed (devtools/client/debugger/src/client/firefox/targets.js#86 ).

Brian, would you have an idea on how to fix that?

Flags: needinfo?(bhackett1024)

we can modify this bug's summary, since we did some investigation here.

Flags: needinfo?(nchevobbe)
Summary: Perma tier 2 devtools/client/webconsole/test/browser/browser_toolbox_console_new_process.js | Test timed out - → Intermittent devtools/client/webconsole/test/browser/browser_toolbox_console_new_process.js | Test timed out -

(In reply to Nicolas Chevobbe [:nchevobbe] from comment #8)

Here's a failure that happens on the test:

...

So the debugger detects a change in threads (threadListChanged) and try to get a target from a descriptor while the connection is being closed (devtools/client/debugger/src/client/firefox/targets.js#86 ).

Brian, would you have an idea on how to fix that?

Hmm, I'm not sure this message would cause the test itself to timeout, and I see timeouts on treeherder that don't include this message. I've tried reproducing this locally on both opt and debug builds without success. Disabling it on affected platforms seems good for now until we can get more of an idea what is causing the timeouts.

Flags: needinfo?(bhackett1024)
Attachment #9107119 - Attachment description: Bug 1591590 - Disable browser_toolbox_console_new_process.js on macos debug and linux debug for frequent failures. r=nchevobbe → Bug 1591590 - Disable browser_toolbox_console_new_process.js on macos debug, linux debug and windows ccov for frequent failures. r=nchevobbe
Pushed by malexandru@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/d3b22e1c0b88
Disable browser_toolbox_console_new_process.js on macos debug, linux debug and windows ccov for frequent failures. r=nchevobbe
Keywords: leave-open, test-disabled
Whiteboard: [retriggered][stockwell disable-recommended] → [retriggered][stockwell disabled]
Flags: needinfo?(nchevobbe)
Assignee: nobody → aryx.bugmail
Status: NEW → ASSIGNED
Attachment #9125454 - Attachment description: Bug 1591590 - Disable browser_toolbox_console_new_process.js also on Linux ccov. r=nchevobbe → Bug 1591590 - Disable browser_toolbox_console_new_process.js also on Linux ccov. r=nchevobbe DONTBUILD
Pushed by archaeopteryx@coole-files.de:
https://hg.mozilla.org/integration/autoland/rev/5d2c3dd4d1c4
Disable browser_toolbox_console_new_process.js also on Linux ccov. r=nchevobbe DONTBUILD

This has:

Most of the failures are on windows10-64 debug (last 7 days). Test is skipped on asan || (os == 'mac' && debug) || (os == 'linux' && debug) || ccov
Nicholas, any chance to have a fix for this test in the near future?

Flags: needinfo?(nchevobbe)
Attached image image.png —

So when it fails it looks like the browser toolbox is in a weird state.

I'm seeing that from time to time.

Flags: needinfo?(nchevobbe)

There are 29 failures associated to this bug in the last 7 days. These are occurring on windows10-64 debug builds.

recent log: https://treeherder.mozilla.org/logviewer.html#?job_id=290546350&repo=autoland

Whiteboard: [retriggered][stockwell disabled] → [retriggered][stockwell disabled][stockell:needswork]
Assignee: aryx.bugmail → nobody
Status: ASSIGNED → NEW
Flags: needinfo?(nchevobbe)

Nicolas can you assign someone to take a look?

I'm looking into it

Assignee: nobody → nchevobbe
Status: NEW → ASSIGNED
Flags: needinfo?(nchevobbe)

Hi Nicolas, are there any updates here?

There are 56 total failures in the last 7 days on

  • windows7-32 debug
  • windows10-6 debug

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

[task 2020-03-22T22:44:06.325Z] 22:44:06 INFO - TEST-START | devtools/client/webconsole/test/browser/browser_toolbox_console_new_process.js
[task 2020-03-22T22:44:06.343Z] 22:44:06 INFO - GECKO(5868) | [Parent 5740, Main Thread] WARNING: NS_ENSURE_TRUE(GetWrapper()) failed: file /builds/worker/checkouts/gecko/dom/ipc/JSWindowActor.cpp, line 66
[task 2020-03-22T22:44:06.363Z] 22:44:06 INFO - GECKO(5868) | [Child 10708: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 0000019C0FCE7800 == 2 [pid = 10708] [id = {a1d126ca-0173-4d4a-a395-a26cb49e943f}]
[task 2020-03-22T22:44:06.365Z] 22:44:06 INFO - GECKO(5868) | [Child 10708: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 3 (0000019C16278430) [pid = 10708] [serial = 55] [outer = 0000000000000000]

[task 2020-03-22T22:50:06.465Z] 22:50:06 INFO - TEST-PASS | devtools/client/webconsole/test/browser/browser_toolbox_console_new_process.js | Has session state -
[task 2020-03-22T22:50:06.465Z] 22:50:06 INFO - Buffered messages logged at 22:44:26
[task 2020-03-22T22:50:06.465Z] 22:50:06 INFO - Console message: [JavaScript Warning: "Use of nsIFile in content process is deprecated." {file: "resource://gre/modules/NetUtil.jsm" line: 253}]
[task 2020-03-22T22:50:06.465Z] 22:50:06 INFO - Console message: [JavaScript Warning: "Use of nsIFile in content process is deprecated." {file: "resource://gre/modules/NetUtil.jsm" line: 253}]
[task 2020-03-22T22:50:06.465Z] 22:50:06 INFO - Console message: [JavaScript Warning: "Use of nsIFile in content process is deprecated." {file: "resource://gre/modules/NetUtil.jsm" line: 253}]
[task 2020-03-22T22:50:06.465Z] 22:50:06 INFO - Console message: [JavaScript Warning: "Use of nsIFile in content process is deprecated." {file: "resource://gre/modules/NetUtil.jsm" line: 253}]
[task 2020-03-22T22:50:06.466Z] 22:50:06 INFO - Console message: [JavaScript Warning: "Use of nsIFile in content process is deprecated." {file: "resource://gre/modules/NetUtil.jsm" line: 253}]
[task 2020-03-22T22:50:06.466Z] 22:50:06 INFO - Buffered messages logged at 22:45:36
[task 2020-03-22T22:50:06.466Z] 22:50:06 INFO - Longer timeout required, waiting longer... Remaining timeouts: 3
[task 2020-03-22T22:50:06.466Z] 22:50:06 INFO - Buffered messages logged at 22:47:06
[task 2020-03-22T22:50:06.466Z] 22:50:06 INFO - Longer timeout required, waiting longer... Remaining timeouts: 2
[task 2020-03-22T22:50:06.466Z] 22:50:06 INFO - Buffered messages logged at 22:48:36
[task 2020-03-22T22:50:06.466Z] 22:50:06 INFO - Longer timeout required, waiting longer... Remaining timeouts: 1
[task 2020-03-22T22:50:06.466Z] 22:50:06 INFO - Buffered messages finished
[task 2020-03-22T22:50:06.466Z] 22:50:06 INFO - TEST-UNEXPECTED-FAIL | devtools/client/webconsole/test/browser/browser_toolbox_console_new_process.js | Test timed out -
[task 2020-03-22T22:50:06.467Z] 22:50:06 INFO - Removing tab.
[task 2020-03-22T22:50:06.467Z] 22:50:06 INFO - Waiting for event: 'TabClose' on [object XULElement].
[task 2020-03-22T22:50:06.467Z] 22:50:06 INFO - Got event: 'TabClose' on [object XULElement].
[task 2020-03-22T22:50:06.467Z] 22:50:06 INFO - Tab removed and finished closing
[task 2020-03-22T22:50:06.472Z] 22:50:06 INFO - TEST-PASS | devtools/client/webconsole/test/browser/browser_toolbox_console_new_process.js | The main process DevToolsServer has no pending connection when the test ends -
[task 2020-03-22T22:50:06.532Z] 22:50:06 INFO - GECKO(5868) | MEMORY STAT | vsize 2104838MB | vsizeMaxContiguous 65492155MB | residentFast 672MB | heapAllocated 265MB
[task 2020-03-22T22:50:06.534Z] 22:50:06 INFO - TEST-OK | devtools/client/webconsole/test/browser/browser_toolbox_console_new_process.js | took 360210ms

Flags: needinfo?(nchevobbe)

Bug 1625181 got backed out for ostensibly turning this into a permafail, but I don't see any direct connection between the two. Perhaps bug 1625181 changed startup timing in a way that uncovered an existing race in this test?

The new failures all appear to be on windows debug builds and this test is already disabled for being too flaky on linux and mac debug.
I really don't see any plausible connection to bug 1625181. Nicolas, can we just disable this test on all debug builds until the devtools team has a chance to study the failures?

(In reply to Andrew Swan [:aswan] from comment #51)

The new failures all appear to be on windows debug builds and this test is already disabled for being too flaky on linux and mac debug.
I really don't see any plausible connection to bug 1625181. Nicolas, can we just disable this test on all debug builds until the devtools team has a chance to study the failures?

sure, let's do that

Flags: needinfo?(nchevobbe)
Attachment #9138522 - Attachment description: Bug 1591590 Disable browser_toolbox_console_new_process.js on win debug n=nchevobbe → Bug 1591590 Disable browser_toolbox_console_new_process.js on win debug r=nchevobbe
Pushed by opoprus@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/ee23e553fe8f
Disable browser_toolbox_console_new_process.js on win debug r=nchevobbe

Recent failures here are mozilla-beta, should the test be disabled there too?

Flags: needinfo?(nchevobbe)

(In reply to Andreea Pavel [:apavel] from comment #59)

Recent failures here are mozilla-beta, should the test be disabled there too?

let's do that

Flags: needinfo?(nchevobbe)

Update:

There have been 31 failures within the last 7 days:

  • 10 failures on Windows 10 x64 Shippable opt
  • 21 failures on Windows 10 x64 opt

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=339769933&repo=autoland&lineNumber=84483

[task 2021-05-15T04:41:43.455Z] 04:41:43     INFO - TEST-PASS | devtools/client/webconsole/test/browser/browser_toolbox_console_new_process.js | Connected - 
[task 2021-05-15T04:41:43.456Z] 04:41:43     INFO - Console message: [JavaScript Warning: "The Web Console logging API (console.log, console.info, console.warn, console.error) has been disabled by a script on this page."]
[task 2021-05-15T04:41:43.456Z] 04:41:43     INFO - Buffered messages logged at 04:39:28
[task 2021-05-15T04:41:43.456Z] 04:41:43     INFO - Longer timeout required, waiting longer...  Remaining timeouts: 3
[task 2021-05-15T04:41:43.457Z] 04:41:43     INFO - Buffered messages logged at 04:40:13
[task 2021-05-15T04:41:43.457Z] 04:41:43     INFO - Longer timeout required, waiting longer...  Remaining timeouts: 2
[task 2021-05-15T04:41:43.457Z] 04:41:43     INFO - Buffered messages logged at 04:40:58
[task 2021-05-15T04:41:43.458Z] 04:41:43     INFO - Longer timeout required, waiting longer...  Remaining timeouts: 1
[task 2021-05-15T04:41:43.458Z] 04:41:43     INFO - Buffered messages finished
[task 2021-05-15T04:41:43.458Z] 04:41:43     INFO - TEST-UNEXPECTED-FAIL | devtools/client/webconsole/test/browser/browser_toolbox_console_new_process.js | Test timed out - 
[task 2021-05-15T04:41:43.459Z] 04:41:43     INFO - Removing tab.
[task 2021-05-15T04:41:43.459Z] 04:41:43     INFO - Waiting for event: 'TabClose' on [object XULElement].
[task 2021-05-15T04:41:43.459Z] 04:41:43     INFO - Got event: 'TabClose' on [object XULElement].
[task 2021-05-15T04:41:43.460Z] 04:41:43     INFO - Tab removed and finished closing
[task 2021-05-15T04:41:43.460Z] 04:41:43     INFO - TEST-PASS | devtools/client/webconsole/test/browser/browser_toolbox_console_new_process.js | The main process DevToolsServer has no pending connection when the test ends -
Whiteboard: [retriggered][stockwell disabled][stockell:needswork] → [retriggered][stockwell disabled][stockwell needswork:owner]
Pushed by abutkovits@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/8f927b85c309
disabale browser_toolbox_console_new_process.js on Win_64_opt for frequent failures. r=intermittent-reviewers,ahal DONTBUILD
Has Regression Range: --- → yes
Severity: normal → S3
Keywords: intermittent-testcase
Summary: Intermittent devtools/client/webconsole/test/browser/browser_toolbox_console_new_process.js | Test timed out - → Intermittent devtools/client/webconsole/test/browser/browser_toolbox_console_new_process.js | single tracking bug
Attachment #9386251 - Attachment is obsolete: true
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: