Closed Bug 1467256 Opened 6 years ago Closed 6 years ago

Intermittent devtools/client/application/test/browser_application_panel_open-links.js | A promise chain failed to handle a rejection: Connection closed, pending error from root, type getProcess failed - stack: _queueResponse/responsePromise

Categories

(DevTools :: Application Panel, defect, P2)

Product:
DevTools
Component:
Application Panel
Type:
defect

Tracking

(firefox61 unaffected, firefox62 fixed, firefox63 fixed)

Status:
RESOLVED FIXED
Milestone:
Firefox 63
Tracking Flags:
Tracking Status
firefox61 --- unaffected
firefox62 --- fixed
firefox63 --- fixed

People

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

References

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell disabled])

Attachments

(2 files)

Bug 1467256 - Wait until about:debugging UI in browser_application_panel_open-links.js;
59 bytes, text/x-review-board-request
ladybenko
: review+
Details
Bug 1467256 - Temporarily disable the test.
59 bytes, text/x-review-board-request
nchevobbe
: review+
Details 
Filed by: rgurzau [at] mozilla.com

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

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

19:05:33     INFO -  17 INFO TEST-START | devtools/client/application/test/browser_application_panel_open-links.js
19:05:33     INFO -  GECKO(3740) | [Parent 3740, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
19:05:33     INFO -  GECKO(3740) | [Child 7836, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
19:05:33     INFO -  GECKO(3740) | [Child 7836, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
19:05:33     INFO -  GECKO(3740) | [Parent 3740, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
19:05:33     INFO -  GECKO(3740) | [Parent 3740, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
19:05:33     INFO -  GECKO(3740) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
19:05:33     INFO -  GECKO(3740) | [Parent 3740, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
19:05:33     INFO -  GECKO(3740) | [Parent 3740, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
19:05:33     INFO -  GECKO(3740) | [Parent 3740, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
19:05:35     INFO -  GECKO(3740) | [Parent 3740, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
19:05:36     INFO -  TEST-INFO | started process screenshot
19:05:36     INFO -  TEST-INFO | screenshot: exit 0
19:05:36     INFO -  Buffered messages logged at 19:05:33
19:05:36     INFO -  18 INFO Entering test bound
19:05:36     INFO -  19 INFO Adding a new tab with URL: http://example.com/browser/devtools/client/application/test/service-workers/empty.html
19:05:36     INFO -  20 INFO Tab added and finished loading
19:05:36     INFO -  Buffered messages logged at 19:05:34
19:05:36     INFO -  21 INFO Console message: [JavaScript Warning: "Use of nsIFile in content process is deprecated." {file: "resource://gre/modules/FileUtils.jsm" line: 170}]
19:05:36     INFO -  22 INFO Console message: [JavaScript Error: "error occurred while processing 'listWorkers: [Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIServiceWorkerManager.getRegistrationByPrincipal]"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: resource://devtools/shared/base-loader.js -> resource://devtools/server/actors/worker.js :: _getServiceWorkerRegistrationInfo :: line 158"  data: no]
19:05:36     INFO -  Stack: _getServiceWorkerRegistrationInfo@resource://devtools/shared/base-loader.js -> resource://devtools/server/actors/worker.js:158:12
19:05:36     INFO -  form@resource://devtools/shared/base-loader.js -> resource://devtools/server/actors/worker.js:54:28
19:05:36     INFO -  onListWorkers/</<.workers<@resource://devtools/shared/base-loader.js -> resource://devtools/server/actors/child-process.js:133:40
19:05:36     INFO -  onListWorkers/<@resource://devtools/shared/base-loader.js -> resource://devtools/server/actors/child-process.js:133:20
19:05:36     INFO -  promise callback*onListWorkers@resource://devtools/shared/base-loader.js -> resource://devtools/server/actors/child-pro" {file: "resource://devtools/shared/base-loader.js -> resource://devtools/server/main.js" line: 1617}]
19:05:36     INFO -  _unknownError@resource://devtools/shared/base-loader.js -> resource://devtools/server/main.js:1617:5
19:05:36     INFO -  _queueResponse/responsePromise<@resource://devtools/shared/base-loader.js -> resource://devtools/server/main.js:1646:27
19:05:36     INFO -  promise callback*_queueResponse@resource://devtools/shared/base-loader.js -> resource://devtools/server/main.js:1628:29
19:05:36     INFO -  onPacket@resource://devtools/shared/base-loader.js -> resource://devtools/server/main.js:1778:7
19:05:36     INFO -  receiveMessage@resource://devtools/shared/base-loader.js -> resource://devtools/shared/transport/transport.js:735:7
19:05:36     INFO -  MessageListener.receiveMessage*_addListener@resource://devtools/shared/base-loader.js -> resource://devtools/shared/transport/transport.js:709:7
19:05:36     INFO -  ready@resource://devtools/shared/base-loader.js -> resource://devtools/shared/transport/transport.js:726:7
19:05:36     INFO -  _onConnection@resource://devtools/shared/base-loader.js -> resource://devtools/server/main.js:1203:5
19:05:36     INFO -  connectToParent@resource://devtools/shared/base-loader.js -> resource://devtools/server/main.js:683:12
19:05:36     INFO -  init/<@resource://devtools/server/startup/content-process.jsm:76:18
19:05:36     INFO -  init@resource://devtools/server/startup/content-process.jsm:69:3
19:05:36     INFO -  onInit@resource://devtools/server/startup/content-process.js:23:5
19:05:36     INFO -  MessageListener.receiveMessage*@resource://devtools/server/startup/content-process.js:32:1
19:05:36     INFO -  Buffered messages logged at 19:05:35
19:05:36     INFO -  23 INFO Opening link in a new tab.
19:05:36     INFO -  24 INFO TEST-PASS | devtools/client/application/test/browser_application_panel_open-links.js | The expected tab was opened. -
19:05:36     INFO -  25 INFO Closing the tab.
19:05:36     INFO -  26 INFO Leaving test bound
19:05:36     INFO -  27 INFO Console message: [JavaScript Warning: "Loading failed for the <script> with source “chrome://devtools/content/aboutdebugging/initializer.js”." {file: "about:debugging#workers" line: 17}]
19:05:36     INFO -  Buffered messages logged at 19:05:36
19:05:36     INFO -  28 INFO Removing tab.
19:05:36     INFO -  29 INFO Waiting for event: 'TabClose' on [object XULElement].
19:05:36     INFO -  30 INFO Got event: 'TabClose' on [object XULElement].
19:05:36     INFO -  31 INFO Tab removed and finished closing
19:05:36     INFO -  Buffered messages finished
19:05:36    ERROR -  32 INFO TEST-UNEXPECTED-FAIL | devtools/client/application/test/browser_application_panel_open-links.js | A promise chain failed to handle a rejection: Connection closed, pending error from root, type getProcess failed - stack: _queueResponse/responsePromise<@resource://devtools/shared/base-loader.js -> resource://devtools/server/main.js:1641:15
19:05:36     INFO -  ensureDOMPromiseRejectionsProcessed@resource://testing-common/PromiseTestUtils.jsm:110:5
Product: Firefox → DevTools
In the last 7 days, there have been 36 failures.
Occurrences per platform and build type:
- linux32 /  opt - 10
- linux64 / asan & opt - 13
- windows10-64 / asan - 13

Here is a recent relevant log file and a snippet with the failure:
https://treeherder.mozilla.org/logviewer.html#?job_id=185200155&repo=mozilla-inbound&lineNumber=1565

[task 2018-06-27T16:32:19.273Z] 16:32:19     INFO - Opening link in a new tab.
[task 2018-06-27T16:32:19.273Z] 16:32:19     INFO - TEST-PASS | devtools/client/application/test/browser_application_panel_open-links.js | The expected tab was opened. - 
[task 2018-06-27T16:32:19.273Z] 16:32:19     INFO - Closing the tab.
[task 2018-06-27T16:32:19.274Z] 16:32:19     INFO - Leaving test bound 
[task 2018-06-27T16:32:19.274Z] 16:32:19     INFO - Console message: [JavaScript Warning: "Loading failed for the <script> with source “chrome://devtools/content/aboutdebugging/initializer.js”." {file: "about:debugging#workers" line: 17}]
[task 2018-06-27T16:32:19.274Z] 16:32:19     INFO - Removing tab.
[task 2018-06-27T16:32:19.275Z] 16:32:19     INFO - Waiting for event: 'TabClose' on [object XULElement].
[task 2018-06-27T16:32:19.275Z] 16:32:19     INFO - Got event: 'TabClose' on [object XULElement].
[task 2018-06-27T16:32:19.275Z] 16:32:19     INFO - Tab removed and finished closing
[task 2018-06-27T16:32:19.275Z] 16:32:19     INFO - Buffered messages finished
[task 2018-06-27T16:32:19.277Z] 16:32:19     INFO - TEST-UNEXPECTED-FAIL | devtools/client/application/test/browser_application_panel_open-links.js | A promise chain failed to handle a rejection: Connection closed, pending error from root, type getProcess failed - stack: _queueResponse/responsePromise<@resource://devtools/shared/base-loader.js -> resource://devtools/server/main.js:1662:15
[task 2018-06-27T16:32:19.277Z] 16:32:19     INFO - ensureDOMPromiseRejectionsProcessed@resource://testing-common/PromiseTestUtils.jsm:110:5
[task 2018-06-27T16:32:19.278Z] 16:32:19     INFO - nextTest@chrome://mochikit/content/browser-test.js:739:7
[task 2018-06-27T16:32:19.279Z] 16:32:19     INFO - async*testScope/test_finish/<@chrome://mochikit/content/browser-test.js:1392:11
[task 2018-06-27T16:32:19.280Z] 16:32:19     INFO - run@chrome://mochikit/content/browser-test.js:1329:9
[task 2018-06-27T16:32:19.280Z] 16:32:19     INFO - Rejection date: Wed Jun 27 2018 16:32:18 GMT+0000 (UTC) - false == true - JS frame :: resource://testing-common/PromiseTestUtils.jsm :: assertNoUncaughtRejections :: line 257

:pbro, can you have a look?
Flags: needinfo?(pbrosset)
Whiteboard: [stockwell needswork]
Redirecting to the application panel component for investigation.
Component: General → Application Panel
Flags: needinfo?(pbrosset) → needinfo?(jdescottes)
Priority: P5 → P2
Assignee: nobody → jdescottes
Status: NEW → ASSIGNED
Flags: needinfo?(jdescottes)
Not sure what increased the failure frequency, but let's try to wait until the about:debugging UI is ready before stopping the test.
I can't reproduce the failure on try so far. I think the fix still makes sense so I would propose to land it and see if it improves the situation.

To explain the reasoning: we have an unhandled promise rejection because a call to an API throws after we closed the connection between the server and the client. Since there is no "transport" anymore, the error cannot be reported to the client, and our framework throws itself instead of catching (because it no longer knows what to do with the error). 

I am not trying to fix the API here. We have so many calls that fail when trying to list service workers at the moment, I don't think we can hope to solve them in the scope of this bug. However I think waiting until about:debugging is loaded should allow us to get the error while DevTools have not been destroyed and therefore avoid this unhandled promise rejection.
Comment on attachment 8990223 [details]
Bug 1467256 - Wait until about:debugging UI in browser_application_panel_open-links.js;

https://reviewboard.mozilla.org/r/255256/#review262782

LGTM! I'm going to land it since we got a warning to fix this asap. Thanks Julian!
Attachment #8990223 - Flags: review?(balbeza) → review+
Pushed by balbeza@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/7939729c9ff1
Wait until about:debugging UI in browser_application_panel_open-links.js;r=ladybenko
https://hg.mozilla.org/mozilla-central/rev/7939729c9ff1
Status: ASSIGNED → RESOLVED
Closed: 6 years ago
status-firefox63: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 63
Attachment #8991290 - Flags: review?(nchevobbe)
Comment on attachment 8991290 [details]
Bug 1467256 - Temporarily disable the test.

https://reviewboard.mozilla.org/r/256224/#review263098

::: devtools/client/application/test/browser.ini
(Diff revision 1)
>  [browser_application_panel_debug-service-worker.js]
>  [browser_application_panel_list-domain-workers.js]
>  [browser_application_panel_list-several-workers.js]
>  [browser_application_panel_list-single-worker.js]
>  [browser_application_panel_list-unicode.js]
> -[browser_application_panel_open-links.js]

We usually add a skip-if=true for disabled tests, as it forces us to come back at it in the future, and also, we can put a reference to the bug.
See for example https://searchfox.org/mozilla-central/rev/a80651653faa78fa4dfbd238d099c2aad1cec304/devtools/client/webconsole/test/mochitest/browser.ini#283-284
Attachment #8991290 - Flags: review?(nchevobbe)
Comment on attachment 8991290 [details]
Bug 1467256 - Temporarily disable the test.

https://reviewboard.mozilla.org/r/256224/#review263112
Attachment #8991290 - Flags: review?(nchevobbe) → review+
Pushed by balbeza@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/a4a611c6bfdd
Temporarily disable the test. r=nchevobbe
I have temporarily disabled the test until we figure out what's going on
https://hg.mozilla.org/mozilla-central/rev/a4a611c6bfdd
Status: REOPENED → RESOLVED
Closed: 6 years ago → 6 years ago
status-firefox63: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 63
This still occurs on mozilla-beta

Failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=187932104&repo=mozilla-beta&lineNumber=1571

[task 2018-07-12T22:56:28.646Z] 22:56:28     INFO - Adding a new tab with URL: http://example.com/browser/devtools/client/application/test/service-workers/empty.html
[task 2018-07-12T22:56:28.646Z] 22:56:28     INFO - Tab added and finished loading
[task 2018-07-12T22:56:28.650Z] 22:56:28     INFO - Buffered messages logged at 22:56:26
[task 2018-07-12T22:56:28.650Z] 22:56:28     INFO - Console message: [JavaScript Warning: "Use of nsIFile in content process is deprecated." {file: "resource://gre/modules/FileUtils.jsm" line: 170}]
[task 2018-07-12T22:56:28.650Z] 22:56:28     INFO - Buffered messages logged at 22:56:27
[task 2018-07-12T22:56:28.650Z] 22:56:28     INFO - Console message: [JavaScript Error: "error occurred while processing 'listWorkers: [Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIServiceWorkerManager.getRegistrationByPrincipal]"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: resource://devtools/shared/base-loader.js -> resource://devtools/server/actors/targets/worker.js :: _getServiceWorkerRegistrationInfo :: line 152"  data: no]
[task 2018-07-12T22:56:28.650Z] 22:56:28     INFO - Stack: _getServiceWorkerRegistrationInfo@resource://devtools/shared/base-loader.js -> resource://devtools/server/actors/targets/worker.js:152:12
[task 2018-07-12T22:56:28.651Z] 22:56:28     INFO - form@resource://devtools/shared/base-loader.js -> resource://devtools/server/actors/targets/worker.js:48:28
[task 2018-07-12T22:56:28.651Z] 22:56:28     INFO - onListWorkers/</<.workers<@resource://devtools/shared/base-loader.js -> resource://devtools/server/actors/targets/content-process.js:140:40
[task 2018-07-12T22:56:28.653Z] 22:56:28     INFO - onListWorkers/<@resource://devtools/shared/base-loader.js -> resource://devtools/server/actors/targets/content-process.js:140:20
[task 2018-07-12T22:56:28.653Z] 22:56:28     INFO - Line: 152, column: 0" {file: "resource://devtools/shared/base-loader.js -> resource://devtools/server/main.js" line: 1638}]
[task 2018-07-12T22:56:28.654Z] 22:56:28     INFO - _unknownError@resource://devtools/shared/base-loader.js -> resource://devtools/server/main.js:1638:5
[task 2018-07-12T22:56:28.655Z] 22:56:28     INFO - _queueResponse/responsePromise<@resource://devtools/shared/base-loader.js -> resource://devtools/server/main.js:1667:27
[task 2018-07-12T22:56:28.657Z] 22:56:28     INFO - 
[task 2018-07-12T22:56:28.659Z] 22:56:28     INFO - Opening link in a new tab.
[task 2018-07-12T22:56:28.659Z] 22:56:28     INFO - TEST-PASS | devtools/client/application/test/browser_application_panel_open-links.js | The expected tab was opened. - 
[task 2018-07-12T22:56:28.660Z] 22:56:28     INFO - Closing the tab.
[task 2018-07-12T22:56:28.661Z] 22:56:28     INFO - Leaving test bound 
[task 2018-07-12T22:56:28.662Z] 22:56:28     INFO - Console message: [JavaScript Warning: "Loading failed for the <script> with source “chrome://devtools/content/aboutdebugging/initializer.js”." {file: "about:debugging#workers" line: 17}]
[task 2018-07-12T22:56:28.663Z] 22:56:28     INFO - Buffered messages logged at 22:56:28
[task 2018-07-12T22:56:28.664Z] 22:56:28     INFO - Removing tab.
[task 2018-07-12T22:56:28.665Z] 22:56:28     INFO - Waiting for event: 'TabClose' on [object XULElement].
[task 2018-07-12T22:56:28.666Z] 22:56:28     INFO - Got event: 'TabClose' on [object XULElement].
[task 2018-07-12T22:56:28.667Z] 22:56:28     INFO - Tab removed and finished closing
[task 2018-07-12T22:56:28.668Z] 22:56:28     INFO - Buffered messages finished
[task 2018-07-12T22:56:28.672Z] 22:56:28     INFO - TEST-UNEXPECTED-FAIL | devtools/client/application/test/browser_application_panel_open-links.js | A promise chain failed to handle a rejection: Connection closed, pending error from root, type getProcess failed - stack: _queueResponse/responsePromise<@resource://devtools/shared/base-loader.js -> resource://devtools/server/main.js:1662:15
[task 2018-07-12T22:56:28.674Z] 22:56:28     INFO - ensureDOMPromiseRejectionsProcessed@resource://testing-common/PromiseTestUtils.jsm:110:5
[task 2018-07-12T22:56:28.674Z] 22:56:28     INFO - nextTest@chrome://mochikit/content/browser-test.js:739:7
[task 2018-07-12T22:56:28.675Z] 22:56:28     INFO - Rejection date: Thu Jul 12 2018 22:56:28 GMT+0000 (UTC) - false == true - JS frame :: resource://testing-common/PromiseTestUtils.jsm :: assertNoUncaughtRejections :: line 257
[task 2018-07-12T22:56:28.676Z] 22:56:28     INFO - Stack trace:
[task 2018-07-12T22:56:28.676Z] 22:56:28     INFO - resource://testing-common/PromiseTestUtils.jsm:assertNoUncaughtRejections:257
[task 2018-07-12T22:56:28.676Z] 22:56:28     INFO - chrome://mochikit/content/browser-test.js:nextTest:740
[task 2018-07-12T22:56:28.677Z] 22:56:28     INFO - GECKO(1046) | JavaScript error: resource://devtools/shared/base-loader.js -> resource://devtools/server/main.js, line 1662: Error: Connection closed, pending error from root, type getProcess failed
[task 2018-07-12T22:56:28.678Z] 22:56:28     INFO - Console message: [JavaScript Error: "Error: Connection closed, pending error from root, type getProcess failed" {file: "resource://devtools/shared/base-loader.js -> resource://devtools/server/main.js" line: 1662}]
[task 2018-07-12T22:56:28.678Z] 22:56:28     INFO - GECKO(1046) | MEMORY STAT | vsize 20974114MB | residentFast 1221MB
[task 2018-07-12T22:56:28.679Z] 22:56:28     INFO - TEST-OK | devtools/client/application/test/browser_application_panel_open-links.js | took 2794ms
[task 2018-07-12T22:56:28.680Z] 22:56:28     INFO - checking window state
[task 2018-07-12T22:56:29.946Z] 22:56:29     INFO - Console message: [JavaScript Warning: "Use of nsIFile in content process is deprecated." {file: "resource://gre/modules/FileUtils.jsm" line: 170}]
[task 2018-07-12T22:56:30.851Z] 22:56:30     INFO - GECKO(1046) | Completed ShutdownLeaks collections in process 1365
[task 2018-07-12T22:56:30.892Z] 22:56:30     INFO - GECKO(1046) | Completed ShutdownLeaks collections in process 1119
[task 2018-07-12T22:56:31.035Z] 22:56:31     INFO - GECKO(1046) | Completed ShutdownLeaks collections in process 1339
[task 2018-07-12T22:56:31.299Z] 22:56:31     INFO - GECKO(1046) | Completed ShutdownLeaks collections in process 1046
[task 2018-07-12T22:56:31.299Z] 22:56:31     INFO - TEST-START | Shutdown
[task 2018-07-12T22:56:31.299Z] 22:56:31     INFO - Browser Chrome Test Summary
[task 2018-07-12T22:56:31.300Z] 22:56:31     INFO - Passed:  17
[task 2018-07-12T22:56:31.301Z] 22:56:31     INFO - Failed:  1
[task 2018-07-12T22:56:31.301Z] 22:56:31     INFO - Todo:    0
[task 2018-07-12T22:56:31.301Z] 22:56:31     INFO - Mode:    e10s
[task 2018-07-12T22:56:31.302Z] 22:56:31     INFO - *** End BrowserChrome Test Results ***
Status: RESOLVED → REOPENED
status-firefox63: fixed → ---
Resolution: FIXED → ---
Keywords: leave-open
Whiteboard: [stockwell disable-recommended] → [stockwell disabled]
Andreea: this was fixed in 63, not sure why the flags were reset? Was your intention to request an uplift to beta?
Flags: needinfo?(apavel)
:jdescottes hi, sorry about that. Aryx clarified what it means when a bug is fixed on mozilla-central but happens on beta. I cannot request uplifts. 

Will reset the flags to how they should be.
status-firefox63: --- → fixed
Flags: needinfo?(apavel)
Status: REOPENED → RESOLVED
Closed: 6 years ago → 6 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: