Intermittent devtools/client/aboutdebugging-new/test/<randomtest>| A promise chain failed to handle a rejection: Connection closed, <more text>

RESOLVED FIXED in Firefox 66

Status

defect
P5
normal
RESOLVED FIXED
8 months ago
5 months ago

People

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

Tracking

({intermittent-failure})

unspecified
Firefox 67
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox66 fixed, firefox67 fixed)

Details

(Whiteboard: [retriggered][stockwell disable-recommended])

Attachments

(8 attachments)

Filed by: rmaries [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=220637015&repo=mozilla-central

https://queue.taskcluster.net/v1/task/EKlOBQndRRaYYpJcU0rwVg/runs/0/artifacts/public/logs/live_backing.log

09:48:55 INFO - TEST-START | devtools/client/aboutdebugging-new/test/browser/browser_aboutdebugging_temporary_addon_install_error.js
09:48:55 INFO - GECKO(1674) | JavaScript error: resource://devtools/server/main.js, line 1192: Error: Connection closed, pending error from root, type getProcess failed
09:48:56 INFO - GECKO(1674) | console.error: "[ACTION FAILED] TEMPORARY_EXTENSION_INSTALL_FAILURE: JSON.parse: unexpected keyword at line 1 column 1 of the JSON data"
09:48:56 INFO - GECKO(1674) | console.error: "readJSON/</<@resource://gre/modules/Extension.jsm:458:19\nonStopRequest@resource://gre/modules/NetUtil.jsm:123:17\n"
09:48:56 INFO - TEST-INFO | started process screencapture
09:48:56 INFO - TEST-INFO | screencapture: exit 0
09:48:56 INFO - Buffered messages logged at 09:48:55
09:48:56 INFO - Entering test bound
09:48:56 INFO - Console message: [JavaScript Error: "Error: Connection closed, pending error from root, type getProcess failed" {file: "resource://devtools/server/main.js" line: 1192}]
09:48:56 INFO - opening about:debugging
09:48:56 INFO - Adding a new tab with URL: about:debugging
09:48:56 INFO - Tab added and finished loading
09:48:56 INFO - wait for the initial about:debugging requests to be successful
09:48:56 INFO - Buffered messages logged at 09:48:56
09:48:56 INFO - Install a bad extension
09:48:56 INFO - Wait until the install error message appears
09:48:56 INFO - TEST-PASS | devtools/client/aboutdebugging-new/test/browser/browser_aboutdebugging_temporary_addon_install_error.js | The expected installation error is displayed: There was an error during the temporary add-on installation.JSON.parse: unexpected keyword at line 1 column 1 of the JSON data -
09:48:56 INFO - Install a valid extension to make the message disappear
09:48:56 INFO - Wait for addon to be installed
09:48:56 INFO - Wait until the error message disappears
09:48:56 INFO - Wait for the temporary addon to be displayed as a debug target
09:48:56 INFO - Remove the temporary extension with name: 'test-temporary-extension'
09:48:56 INFO - Wait until the debug target item disappears
09:48:56 INFO - Removing tab.
09:48:56 INFO - Waiting for event: 'TabClose' on [object XULElement].
09:48:56 INFO - Got event: 'TabClose' on [object XULElement].
09:48:56 INFO - Tab removed and finished closing
09:48:56 INFO - Buffered messages finished
09:48:56 INFO - TEST-UNEXPECTED-FAIL | devtools/client/aboutdebugging-new/test/browser/browser_aboutdebugging_temporary_addon_install_error.js | A promise chain failed to handle a rejection: Connection closed, pending error from root, type getProcess failed - stack: _queueResponse/responsePromise<@resource://devtools/server/main.js:1192:15
09:48:56 INFO - promise callback*_queueResponse@resource://devtools/server/main.js:1190:8
09:48:56 INFO - onPacket@resource://devtools/server/main.js:1340:7
09:48:56 INFO - send/<@resource://devtools/shared/transport/local-transport.js:64:11
09:48:56 INFO - exports.makeInfallible/<@resource://devtools/shared/ThreadSafeDevToolsUtils.js:109:14
09:48:56 INFO - DevToolsUtils.executeSoonexports.executeSoon@resource://devtools/shared/DevToolsUtils.js:57:21
09:48:56 INFO - send@resource://devtools/shared/transport/local-transport.js:58:7
09:48:56 INFO - send@resource://devtools/shared/protocol.js:1399:9
09:48:56 INFO - request@resource://devtools/shared/protocol.js:1417:5
09:48:56 INFO - generateRequestMethods/</frontProto[name]@resource://devtools/shared/protocol.js:1539:14
09:48:56 INFO - getProcess@resource://devtools/shared/fronts/root.js:150:28
09:48:56 INFO - async
listAllWorkers@resource://devtools/shared/fronts/root.js:71:29
09:48:56 INFO - asynclistWorkers@resource://devtools/client/aboutdebugging-new/src/modules/client-wrapper.js:120:46
09:48:56 INFO - async
requestWorkers/<@resource://devtools/client/aboutdebugging-new/src/actions/debug-targets.js:203:17
09:48:56 INFO - asyncthunk/</<@resource://devtools/client/shared/redux/middleware/thunk.js:15:9
09:48:56 INFO - dispatch@resource://devtools/client/shared/vendor/redux.js:755:18
09:48:56 INFO - onWorkersUpdated@resource://devtools/client/aboutdebugging-new/src/middleware/debug-target-listener.js:25:5
09:48:56 INFO - emit@resource://devtools/shared/event-emitter.js:186:15
09:48:56 INFO - emit@resource://devtools/shared/event-emitter.js:267:5
09:48:56 INFO - onPacket@resource://devtools/shared/protocol.js:1453:7
09:48:56 INFO - onPacket@resource://devtools/shared/client/debugger-client.js:765:7
09:48:56 INFO - send/<@resource://devtools/shared/transport/local-transport.js:64:11
09:48:56 INFO - exports.makeInfallible/<@resource://devtools/shared/ThreadSafeDevToolsUtils.js:109:14
09:48:56 INFO - DevToolsUtils.executeSoon
exports.executeSoon@resource://devtools/shared/DevToolsUtils.js:57:21
09:48:56 INFO - send@resource://devtools/shared/transport/local-transport.js:58:7
09:48:56 INFO - send@resource://devtools/server/main.js:1031:5
09:48:56 INFO - onProcessListChanged@resource://devtools/server/actors/root.js:531:5
09:48:56 INFO - _notifyListChanged@resource://devtools/server/actors/process.js:74:7
09:48:56 INFO - _onMessage@resource://devtools/server/actors/process.js:83:5
09:48:56 INFO - MessageListener.receiveMessage*_checkListening@resource://devtools/server/actors/process.js:64:7
09:48:56 INFO - getList@resource://devtools/server/actors/process.js:37:5
09:48:56 INFO - onListProcesses@resource://devtools/server/actors/root.js:526:18
09:48:56 INFO - onPacket@resource://devtools/server/main.js:1324:15
09:48:56 INFO - send/<@resource://devtools/shared/transport/local-transport.js:64:11
09:48:56 INFO - exports.makeInfallible/<@resource://devtools/shared/ThreadSafeDevToolsUtils.js:109:14
09:48:56 INFO - DevToolsUtils.executeSoonexports.executeSoon@resource://devtools/shared/DevToolsUtils.js:57:21
09:48:56 INFO - send@resource://devtools/shared/transport/local-transport.js:58:7
09:48:56 INFO - send@resource://devtools/shared/protocol.js:1399:9
09:48:56 INFO - request@resource://devtools/shared/protocol.js:1417:5
09:48:56 INFO - generateRequestMethods/</frontProto[name]@resource://devtools/shared/protocol.js:1539:14
09:48:56 INFO - listAllWorkers@resource://devtools/shared/fronts/root.js:65:35
09:48:56 INFO - async
listWorkers@resource://devtools/client/aboutdebugging-new/src/modules/client-wrapper.js:120:46
09:48:56 INFO - asyncrequestWorkers/<@resource://devtools/client/aboutdebugging-new/src/actions/debug-targets.js:203:17
09:48:56 INFO - async
thunk/</<@resource://devtools/client/shared/redux/middleware/thunk.js:15:9
09:48:56 INFO - dispatch@resource://devtools/client/shared/vendor/redux.js:755:18
09:48:56 INFO - Rejection date: Tue Jan 08 2019 09:48:55 GMT-0800 (Pacific Standard Time) - false == true - JS frame :: resource://testing-common/PromiseTestUtils.jsm :: assertNoUncaughtRejections :: line 257
09:48:56 INFO - Stack trace:
09:48:56 INFO - resource://testing-common/PromiseTestUtils.jsm:assertNoUncaughtRejections:257
09:48:56 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1131
09:48:56 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1097
09:48:56 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:990
09:48:56 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:803
09:48:56 INFO - Leaving test bound
09:48:56 INFO - GECKO(1674) | MEMORY STAT | vsize 4475MB | residentFast 426MB | heapAllocated 185MB

It may be related to some of the patch yulia landed, but I'm not sure about this.
If that's not related, Julian might have some ideas.

Flags: needinfo?(ystartsev)
Flags: needinfo?(nchevobbe)
Flags: needinfo?(jdescottes)

This shouldn't be related to my patches, since they haven't landed yet, but it looks like the same type of failure -- we are not waiting for something on shutdown. It isn't the rdp shutdown request though...

Flags: needinfo?(ystartsev)

Thanks for the ping. I have seen the getProcess failures become more frequent recently as well, but I have issues reproducing consistently for now, so it is hard to investigate. Keeping the ni? to try to spend more time on it when possible.

Flags: needinfo?(jdescottes)
Flags: needinfo?(jdescottes)
Summary: Perma tier2 devtools/client/aboutdebugging-new/test/browser/browser_aboutdebugging_temporary_addon_install_error.js | A promise chain failed to handle a rejection: Connection closed, pending error from root, type getProcess failed - stack: _queueResponse/ → Perma tier2 devtools/client/aboutdebugging-new/test/<randomtest>| A promise chain failed to handle a rejection: Connection closed, <more text>
Summary: Perma tier2 devtools/client/aboutdebugging-new/test/<randomtest>| A promise chain failed to handle a rejection: Connection closed, <more text> → Intermittent devtools/client/aboutdebugging-new/test/<randomtest>| A promise chain failed to handle a rejection: Connection closed, <more text>

Julien, this appeared here https://hg.mozilla.org/mozilla-central/pushloghtml?changeset=cc4350821ea2def4ed60e47e0eaad5e82403fb4d so I assume it is caused by bug 1500383. I looked at all the duplicates Aryx closed and all of them are made after this one was filed.

Whiteboard: [stockwell needswork:owner]
Whiteboard: [stockwell needswork:owner] → [stockwell needswork:owner][retriggered]

Cristina, please see the discussion earlier in this bug. The issue started earlier, the frequency of this bug peaked because all those occurrences independent from the test in which they fail started to get classified with it this week.

Flags: needinfo?(echen) → needinfo?(ccoroiu)

:aryx, thank you for your input

Flags: needinfo?(ccoroiu)

I will spend some time on this today, but I am wondering how we can assess the urgency of intermittent bugs? This one is filed as P5, but the last comment from the bot is "It should be disabled until it can be fixed." and it now has the whiteboard tag [stockwell disable-recommended].

Considering that this bug is actually aggregating failures for many tests, disabling all of them would be a real problem for us. We have to prioritize working on intermittents against working on other features for the project. Is the priority supposed to be updated when the intermittent becomes urgent to look at from sheriff's point of view? Or should we look at something else?

Flags: needinfo?(jdescottes) → needinfo?(aryx.bugmail)

The P5 gets set as default for intermittent bugs. At the current failure rate, the whole aboutdebugging-new folder won't get disabled for now, but it still consumes sheriffing time (manually retrieving the bug number and adding it for classification, ~140 times last week) and adds confusion to people using Try (~420 failures last week). It's at the highest or second highest level of urgency for intermittents (jmaher runs the intermittent management and knows the complete intermittent triaging system).

Flags: needinfo?(aryx.bugmail)

Julian, we don't usually change the priority of intermittent bugs. We triage them and try to find the cause and similarities and we ask the developer or triage owner to take it from there. If they decide to change the priority, they will. We only do this when trees are closed and the bug is blocker.

When it comes to disabling bugs, we do the same, ask the developer if he wants the test to be disabled or if he wants to fix it another way (well, we mostly do that. Where there is not activity whatsoever on the bug and failure rate is high, we disable it directly).

I see thanks for the info. From your last comment, I understand there is a clear needinfo where the developer has to choose between fixing or disabling.

(In reply to Julian Descottes [:jdescottes][:julian] from comment #33)

I see thanks for the info. From your last comment, I understand there is a clear needinfo where the developer has to choose between fixing or disabling.

Yes. however, in this case, as you mentioned, disabling is not an option because there are multiple tests failing.

Whiteboard: [retriggered][stockwell disable-recommended] → [retriggered][stockwell needswork:owner]
Assignee: nobody → jdescottes
Status: NEW → ASSIGNED

This will make it easier to mock the behavior

Depends on D18234
Most tests will now need to use the mocks helper to avoid loading the regular client-wrapper.

Depends on D18235

The two parameters in the openAboutDebugging are a leftover from the original helper of the old about:debugging.

Depends on D18236
Worker updates are very hard to predict and we have many intermittents caused by pending requests
for workers while we destroy the client.

Discussed with @ochameau about the potential solutions, and disabling worker updates in tests that don't need them seems a good option. A complementary solution can be to wait for debugger-client waitForRequestsToSettle (different from our current helper in head.js).

Here is a try with 100 retriggers of about:debugging tests https://treeherder.mozilla.org/#/jobs?repo=try&revision=840935b82e9232076ed94319d6fa9008d86d10af no failure.

Julian, can we land this?

Flags: needinfo?(jdescottes)

I am waiting for reviews.

Belén, I only kept the review request for the patch impacting src/. For the test part, I think the reviews for Daisuke can be enough here. Can you take a look?

Flags: needinfo?(jdescottes) → needinfo?(balbeza)
Attachment #9040450 - Attachment description: Bug 1518581 - Require mocks helper in aboutdebugging head.js;r=ladybenko,daisuke → Bug 1518581 - Require mocks helper in aboutdebugging head.js;r=daisuke
Duplicate of this bug: 1524667

+r in phabricator

Flags: needinfo?(balbeza)
Attachment #9040451 - Attachment description: Bug 1518581 - Remove unused parameters from openAboutDebugging;r=ladybenko,daisuke → Bug 1518581 - Remove unused parameters from openAboutDebugging;r=daisuke
Attachment #9040452 - Attachment description: Bug 1518581 - Silence worker updates if they are not required by the test;r=ladybenko,daisuke → Bug 1518581 - Silence worker updates if they are not required by the test;r=daisuke
Pushed by jdescottes@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/8471b0838846
Move worker listening logic to client wrapper;r=ladybenko,daisuke
https://hg.mozilla.org/integration/autoland/rev/19db6496398d
Require mocks helper in aboutdebugging head.js;r=daisuke
https://hg.mozilla.org/integration/autoland/rev/64aafe3fc812
Remove unused parameters from openAboutDebugging;r=daisuke
https://hg.mozilla.org/integration/autoland/rev/4858ed100ad4
Silence worker updates if they are not required by the test;r=daisuke,ochameau

merge issue with tests that changed since my initial patch... 2 lines fix coming

Backed out 4 changesets (Bug 1518581) for devtools failures

Push with failures: https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=4858ed100ad4e45cafc453362a17bc7fc0dbaed5&selectedJob=228356454

Backout link: https://hg.mozilla.org/integration/autoland/rev/9d7a50ad7fc65340a4f66f0b98dcf27f8efcbf49

Failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=228356454&repo=autoland&lineNumber=1209

01:27:07 INFO - TEST-OK | devtools/client/aboutdebugging-new/test/browser/browser_aboutdebugging_persist_connection.js | took 1429ms
01:27:07 INFO - checking window state
01:27:07 INFO - TEST-START | devtools/client/aboutdebugging-new/test/browser/browser_aboutdebugging_profiler_dialog.js
01:27:07 INFO - TEST-INFO | started process screencapture
01:27:07 INFO - TEST-INFO | screencapture: exit 0
01:27:07 INFO - TEST-UNEXPECTED-FAIL | devtools/client/aboutdebugging-new/test/browser/browser_aboutdebugging_profiler_dialog.js | Exception thrown - at chrome://mochitests/content/browser/devtools/client/aboutdebugging-new/test/browser/helper-mocks.js:1 - SyntaxError: redeclaration of let Mocks
01:27:07 INFO - GECKO(1995) | MEMORY STAT | vsize 4753MB | residentFast 679MB | heapAllocated 282MB
01:27:07 INFO - TEST-OK | devtools/client/aboutdebugging-new/test/browser/browser_aboutdebugging_profiler_dialog.js | took 19ms
01:27:07 INFO - checking window state

Flags: needinfo?(jdescottes)
Flags: needinfo?(jdescottes)
Pushed by jdescottes@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/7c4448d6404e
Move worker listening logic to client wrapper;r=ladybenko,daisuke
https://hg.mozilla.org/integration/autoland/rev/7c8b1588b4a5
Require mocks helper in aboutdebugging head.js;r=daisuke
https://hg.mozilla.org/integration/autoland/rev/a01d9c68d22e
Remove unused parameters from openAboutDebugging;r=daisuke
https://hg.mozilla.org/integration/autoland/rev/f8c6ff529995
Silence worker updates if they are not required by the test;r=daisuke,ochameau
Blocks: 1528140
Duplicate of this bug: 1521244

Nevermind, found Bug 1528140 meanwhile. Sorry for the messup.

Yes it's already been mentioned in another bug, but I must say again that the issues are different. Only the error message happens to be similar, but they should not be mixed together. I wish the other bug was updated.

Flags: needinfo?(jdescottes)
Duplicate of this bug: 1521244
Depends on: 1528946
Duplicate of this bug: 1528946
Duplicate of this bug: 1516414

This is a pretty noisy failure on Beta too. The patches graft cleanly - would they be reasonably safe to uplift? Looks like the first one isn't entirely test-only, hence why I ask.

Flags: needinfo?(jdescottes)

Is there a link where I can see the failures on Beta? Before deciding to uplift anything I want to make sure this is really the same issue. Being a "meta" intermittent, the signature is not really accurate, and some failures have been linked to this bug incorrectly.

(also if we uplift this Bug, we need to make sure we uplift Bug 1528140 which will probably start spiking in Beta)

Flags: needinfo?(jdescottes) → needinfo?(ryanvm)

(patches rebased on beta for both this bug and Bug 1528140)

(In reply to Julian Descottes [:jdescottes] from comment #74)

Is there a link where I can see the failures on Beta?

https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2018-10-28&endday=2019-02-25&tree=firefox-releases&bug=1518581

Flags: needinfo?(ryanvm)

Comment on attachment 9045889 [details] [diff] [review]
bug1518581-part1-beta.patch

Beta/Release Uplift Approval Request

  • Feature/Bug causing the regression: None
  • User impact if declined: intermittent failures on CI
  • Is this code covered by automated tests?: Yes
  • Has the fix been verified in Nightly?: No
  • Needs manual test from QE?: No
  • If yes, steps to reproduce:
  • List of other uplifts needed: Bug 1528140
  • Risk to taking this patch: Low
  • Why is the change risky/not risky? (and alternatives if risky): On central for 10 days, mostly test change. Non test-change is on a preffed off UI.
  • String changes made/needed:
Attachment #9045889 - Flags: approval-mozilla-beta?

Comment on attachment 9045890 [details] [diff] [review]
bug1518581-part2-beta.patch

Beta/Release Uplift Approval Request

  • Feature/Bug causing the regression: None
  • User impact if declined: intermittent failures on CI
  • Is this code covered by automated tests?: Yes
  • Has the fix been verified in Nightly?: No
  • Needs manual test from QE?: No
  • If yes, steps to reproduce:
  • List of other uplifts needed: Bug 1528140
  • Risk to taking this patch: Low
  • Why is the change risky/not risky? (and alternatives if risky): On central for 10 days, mostly test change. Non test-change is on a preffed off UI.
  • String changes made/needed:
Attachment #9045890 - Flags: approval-mozilla-beta?

Comment on attachment 9045891 [details] [diff] [review]
bug1518581-part3-beta.patch

Beta/Release Uplift Approval Request

  • Feature/Bug causing the regression: None
  • User impact if declined: intermittent failures on CI
  • Is this code covered by automated tests?: Yes
  • Has the fix been verified in Nightly?: No
  • Needs manual test from QE?: No
  • If yes, steps to reproduce:
  • List of other uplifts needed: Bug 1528140
  • Risk to taking this patch: Low
  • Why is the change risky/not risky? (and alternatives if risky): On central for 10 days, mostly test change. Non test-change is on a preffed off UI.
  • String changes made/needed:
Attachment #9045891 - Flags: approval-mozilla-beta?

Comment on attachment 9045892 [details] [diff] [review]
bug1518581-part4-beta.patch

Beta/Release Uplift Approval Request

  • Feature/Bug causing the regression: None
  • User impact if declined: intermittent failures on CI
  • Is this code covered by automated tests?: Yes
  • Has the fix been verified in Nightly?: No
  • Needs manual test from QE?: No
  • If yes, steps to reproduce:
  • List of other uplifts needed: Bug 1528140
  • Risk to taking this patch: Low
  • Why is the change risky/not risky? (and alternatives if risky): On central for 10 days, mostly test change. Non test-change is on a preffed off UI.
  • String changes made/needed:
Attachment #9045892 - Flags: approval-mozilla-beta?

thanks, looks like the same failure then. Requesting uplift.

Comment on attachment 9045889 [details] [diff] [review]
bug1518581-part1-beta.patch

Test changes (mostly). OK for uplift for beta 12.
Attachment #9045889 - Flags: approval-mozilla-beta? → approval-mozilla-beta+
Attachment #9045890 - Flags: approval-mozilla-beta? → approval-mozilla-beta+
Attachment #9045891 - Flags: approval-mozilla-beta? → approval-mozilla-beta+
Attachment #9045892 - Flags: approval-mozilla-beta? → approval-mozilla-beta+

This is rather https://bugzilla.mozilla.org/show_bug.cgi?id=1528140, it seems like we missed one test when uplifting the fixes in the other bug (browser_aboutdebugging_devtoolstoolbox_contextmenu). If you need to fix it before the end of this beta cycle can you ni? ladybenko?

Flags: needinfo?(jdescottes)
You need to log in before you can comment on or make changes to this bug.