Intermittent devtools/client/aboutdebugging/test/browser/browser_aboutdebugging_addons_debug_inspector.js | A promise chain failed to handle a rejection: Connection closed, pending request to server0.conn5.preferenceActor23, type getBoolPref failed
Categories
(DevTools :: about:debugging, defect, P5)
Tracking
(firefox80 fixed)
Tracking | Status | |
---|---|---|
firefox80 | --- | fixed |
People
(Reporter: intermittent-bug-filer, Assigned: jdescottes)
Details
(Keywords: intermittent-failure)
Attachments
(3 files)
Filed by: malexandru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=308548578&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/EBN8hF0HTvO9aaPg0IaeQw/runs/0/artifacts/public/logs/live_backing.log
[task 2020-07-04T00:58:50.291Z] 00:58:50 INFO - TEST-START | devtools/client/aboutdebugging/test/browser/browser_aboutdebugging_addons_debug_inspector.js
[task 2020-07-04T00:58:50.334Z] 00:58:50 INFO - GECKO(5328) | [Parent 6772: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 0000024BB24AE000 == 16 [pid = 6772] [id = {d0bdd1d3-1713-4e5f-9b0e-99ace3c057cb}]
[task 2020-07-04T00:58:50.334Z] 00:58:50 INFO - GECKO(5328) | [Parent 6772: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 41 (0000024BBF0B3C10) [pid = 6772] [serial = 46] [outer = 0000000000000000]
[task 2020-07-04T00:58:50.334Z] 00:58:50 INFO - GECKO(5328) | [Parent 6772: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 42 (0000024BB4CAA400) [pid = 6772] [serial = 47] [outer = 0000024BBF0B3C10]
[task 2020-07-04T00:58:50.393Z] 00:58:50 INFO - GECKO(5328) | [Parent 6772: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 43 (0000024BBACA0C00) [pid = 6772] [serial = 48] [outer = 0000024BBF0B3C10]
[task 2020-07-04T00:58:50.403Z] 00:58:50 INFO - GECKO(5328) | [Parent 6772, Main Thread] WARNING: Failed to retarget HTML data delivery to the parser thread.: file /builds/worker/checkouts/gecko/parser/html/nsHtml5StreamParser.cpp, line 1131
[task 2020-07-04T00:58:50.495Z] 00:58:50 INFO - GECKO(5328) | [Child 8004: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 3 (000001FAD317C800) [pid = 8004] [serial = 5] [outer = 0000000000000000] [url = about:blank]
[task 2020-07-04T00:58:50.901Z] 00:58:50 INFO - GECKO(5328) | [Child 844: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 00000203ED6B4000 == 5 [pid = 844] [id = {c731b4f8-d0a8-4ea5-b0f1-cf765250ad97}] [url = moz-extension://59803e5c-0ad7-4ade-a369-0e52f4fea4da/_generated_background_page.html]
[task 2020-07-04T00:58:50.901Z] 00:58:50 INFO - GECKO(5328) | [Child 844: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 00000203ED6B9000 == 4 [pid = 844] [id = {90abcb20-4a99-404a-9722-c009602f6990}] [url = about:blank]
[task 2020-07-04T00:58:53.199Z] 00:58:53 INFO - GECKO(5328) | [Parent 6772, Main Thread] WARNING: Need BrowserChild to get the nativeWindow from!: file /b[Child 844: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 00000203ED6B6800 == 5 [pid = 844] [id = {2d7d717e-4c07-4f56-8526-70968d8b7345}]
[task 2020-07-04T00:58:53.199Z] 00:58:53 INFO - GECKO(5328) | uilds/worker/checkouts/gecko/widget/PuppetWidget.[Child 844: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 13 (00000203ECD5F260) [pid = 844] [serial = 28] [outer = 0000000000000000]
[task 2020-07-04T00:58:53.199Z] 00:58:53 INFO - GECKO(5328) | cpp, line 1086
[task 2020-07-04T00:58:53.199Z] 00:58:53 INFO - GECKO(5328) | [Child 844: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 14 (00000203ED6B9400) [pid = 844] [serial = 29] [outer = 00000203ECD5F260]
[task 2020-07-04T00:58:53.209Z] 00:58:53 INFO - GECKO(5328) | [Child 844, Main Thread] WARNING: Fallback to BasicLayerManager: file /builds/worker/checkouts/gecko/dom/ipc/BrowserChild.cpp, line 2633
[task 2020-07-04T00:58:53.235Z] 00:58:53 INFO - GECKO(5328) | [Child 844: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 15 (00000203EF5E2800) [pid = 844] [serial = 30] [outer = 00000203ECD5F260]
[task 2020-07-04T00:58:53.367Z] 00:58:53 INFO - GECKO(5328) | [Parent 6772: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 0000024BBDE19400 == 17 [pid = 6772] [id = {018b5c55-b1cb-4efe-bcbc-4bd9ee372b7a}]
[task 2020-07-04T00:58:53.367Z] 00:58:53 INFO - GECKO(5328) | [Parent 6772: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 44 (0000024BBF0B48C0) [pid = 6772] [serial = 49] [outer = 0000000000000000]
<...>
[task 2020-07-04T00:58:59.155Z] 00:58:59 INFO - TEST-PASS | devtools/client/aboutdebugging/test/browser/browser_aboutdebugging_addons_debug_inspector.js | test-devtools-webextension tab target appeared -
[task 2020-07-04T00:58:59.155Z] 00:58:59 INFO - TEST-PASS | devtools/client/aboutdebugging/test/browser/browser_aboutdebugging_addons_debug_inspector.js | Inspect button for test-devtools-webextension appeared -
[task 2020-07-04T00:58:59.155Z] 00:58:59 INFO - Buffered messages logged at 00:58:54
[task 2020-07-04T00:58:59.155Z] 00:58:59 INFO - Console message: [JavaScript Warning: "Storage access automatically granted for origin “null” on “null”."]
[task 2020-07-04T00:58:59.155Z] 00:58:59 INFO - Buffered messages logged at 00:58:56
[task 2020-07-04T00:58:59.155Z] 00:58:59 INFO - Wait for about:devtools-toolbox tab will be selected
[task 2020-07-04T00:58:59.155Z] 00:58:59 INFO - Wait for the toolbox to close
[task 2020-07-04T00:58:59.155Z] 00:58:59 INFO - Removing tab.
[task 2020-07-04T00:58:59.155Z] 00:58:59 INFO - Waiting for event: 'TabClose' on [object XULElement].
[task 2020-07-04T00:58:59.156Z] 00:58:59 INFO - Got event: 'TabClose' on [object XULElement].
[task 2020-07-04T00:58:59.156Z] 00:58:59 INFO - Tab removed and finished closing
[task 2020-07-04T00:58:59.156Z] 00:58:59 INFO - Buffered messages logged at 00:58:58
[task 2020-07-04T00:58:59.156Z] 00:58:59 INFO - TEST-PASS | devtools/client/aboutdebugging/test/browser/browser_aboutdebugging_addons_debug_inspector.js | Addon toolbox closed -
[task 2020-07-04T00:58:59.156Z] 00:58:59 INFO - Wait for removable extension with name: 'test-devtools-webextension'
[task 2020-07-04T00:58:59.156Z] 00:58:59 INFO - Console message: [JavaScript Error: "Error: Connection closed, pending request to server0.conn5.preferenceActor23, type getBoolPref failed
[task 2020-07-04T00:58:59.156Z] 00:58:59 INFO -
[task 2020-07-04T00:58:59.156Z] 00:58:59 INFO - Request stack:
[task 2020-07-04T00:58:59.156Z] 00:58:59 INFO - request@resource://devtools/shared/protocol/Front.js:256:14
[task 2020-07-04T00:58:59.156Z] 00:58:59 INFO - generateRequestMethods/</frontProto[name]@resource://devtools/shared/protocol/Front/FrontClassWithSpec.js:47:19
[task 2020-07-04T00:58:59.156Z] 00:58:59 INFO - _isDisableAutohideEnabled@resource://devtools/client/framework/toolbox.js:3102:22
[task 2020-07-04T00:58:59.156Z] 00:58:59 INFO - async*_buildTabs@resource://devtools/client/framework/toolbox.js:1811:34
[task 2020-07-04T00:58:59.157Z] 00:58:59 INFO - open/<@resource://devtools/client/framework/toolbox.js:871:12
[task 2020-07-04T00:58:59.157Z] 00:58:59 INFO - Async*open@resource://devtools/client/framework/toolbox.js:984:18
[task 2020-07-04T00:58:59.157Z] 00:58:59 INFO - createToolbox@resource://devtools/client/framework/devtools.js:625:19
[task 2020-07-04T00:58:59.157Z] 00:58:59 INFO - async*showToolbox@resource://devtools/client/framework/devtools.js:512:35
[task 2020-07-04T00:58:59.157Z] 00:58:59 INFO - initToolbox@chrome://devtools/content/framework/toolbox-init.js:152:21
[task 2020-07-04T00:58:59.157Z] 00:58:59 INFO - async*@chrome://devtools/content/framework/toolbox-init.js:162:14
[task 2020-07-04T00:58:59.157Z] 00:58:59 INFO - " {file: "resource://devtools/shared/protocol/Front.js" line: 77}]
[task 2020-07-04T00:58:59.157Z] 00:58:59 INFO - Remove the temporary extension with name: 'test-devtools-webextension'
[task 2020-07-04T00:58:59.157Z] 00:58:59 INFO - Wait until the debug target item disappears
[task 2020-07-04T00:58:59.157Z] 00:58:59 INFO - Buffered messages logged at 00:58:59
[task 2020-07-04T00:58:59.157Z] 00:58:59 INFO - Removing tab.
[task 2020-07-04T00:58:59.157Z] 00:58:59 INFO - Waiting for event: 'TabClose' on [object XULElement].
[task 2020-07-04T00:58:59.157Z] 00:58:59 INFO - Got event: 'TabClose' on [object XULElement].
[task 2020-07-04T00:58:59.158Z] 00:58:59 INFO - Tab removed and finished closing
[task 2020-07-04T00:58:59.158Z] 00:58:59 INFO - Buffered messages finished
[task 2020-07-04T00:58:59.158Z] 00:58:59 INFO - TEST-UNEXPECTED-FAIL | devtools/client/aboutdebugging/test/browser/browser_aboutdebugging_addons_debug_inspector.js | A promise chain failed to handle a rejection: Connection closed, pending request to server0.conn5.preferenceActor23, type getBoolPref failed
[task 2020-07-04T00:58:59.158Z] 00:58:59 INFO -
[task 2020-07-04T00:58:59.158Z] 00:58:59 INFO - Request stack:
[task 2020-07-04T00:58:59.158Z] 00:58:59 INFO - request@resource://devtools/shared/protocol/Front.js:256:14
[task 2020-07-04T00:58:59.158Z] 00:58:59 INFO - generateRequestMethods/</frontProto[name]@resource://devtools/shared/protocol/Front/FrontClassWithSpec.js:47:19
[task 2020-07-04T00:58:59.158Z] 00:58:59 INFO - _isDisableAutohideEnabled@resource://devtools/client/framework/toolbox.js:3102:22
[task 2020-07-04T00:58:59.158Z] 00:58:59 INFO - async*_buildTabs@resource://devtools/client/framework/toolbox.js:1811:34
[task 2020-07-04T00:58:59.158Z] 00:58:59 INFO - open/<@resource://devtools/client/framework/toolbox.js:871:12
[task 2020-07-04T00:58:59.158Z] 00:58:59 INFO - Async*open@resource://devtools/client/framework/toolbox.js:984:18
[task 2020-07-04T00:58:59.158Z] 00:58:59 INFO - createToolbox@resource://devtools/client/framework/devtools.js:625:19
[task 2020-07-04T00:58:59.158Z] 00:58:59 INFO - async*showToolbox@resource://devtools/client/framework/devtools.js:512:35
[task 2020-07-04T00:58:59.158Z] 00:58:59 INFO - initToolbox@chrome://devtools/content/framework/toolbox-init.js:152:21
[task 2020-07-04T00:58:59.158Z] 00:58:59 INFO - async*@chrome://devtools/content/framework/toolbox-init.js:162:14
[task 2020-07-04T00:58:59.158Z] 00:58:59 INFO - - stack: destroy@resource://devtools/shared/protocol/Front.js:77:23
[task 2020-07-04T00:58:59.158Z] 00:58:59 INFO - onClosed@resource://devtools/client/devtools-client.js:629:12
[task 2020-07-04T00:58:59.158Z] 00:58:59 INFO - close@resource://devtools/shared/transport/local-transport.js:169:20
[task 2020-07-04T00:58:59.158Z] 00:58:59 INFO - close@resource://devtools/shared/transport/local-transport.js:165:13
[task 2020-07-04T00:58:59.158Z] 00:58:59 INFO - close@resource://devtools/shared/transport/local-transport.js:165:13
[task 2020-07-04T00:58:59.159Z] 00:58:59 INFO - cleanup@resource://devtools/client/devtools-client.js:124:27
[task 2020-07-04T00:58:59.159Z] 00:58:59 INFO - close/promise<@resource://devtools/client/devtools-client.js:140:7
[task 2020-07-04T00:58:59.159Z] 00:58:59 INFO - close@resource://devtools/client/devtools-client.js:117:21
[task 2020-07-04T00:58:59.159Z] 00:58:59 INFO - _destroyTarget@resource://devtools/client/fronts/targets/target-mixin.js:574:30
[task 2020-07-04T00:58:59.159Z] 00:58:59 INFO - destroy@resource://devtools/client/fronts/targets/target-mixin.js:550:12
[task 2020-07-04T00:58:59.159Z] 00:58:59 INFO - destroy@resource://devtools/client/fronts/targets/browsing-context.js:129:27
[task 2020-07-04T00:58:59.159Z] 00:58:59 INFO - _destroyToolbox/onceDestroyed</<@resource://devtools/client/framework/toolbox.js:3784:32
[task 2020-07-04T00:58:59.159Z] 00:58:59 INFO - promise callback*_destroyToolbox/onceDestroyed<@resource://devtools/client/framework/toolbox.js:3749:12
[task 2020-07-04T00:58:59.159Z] 00:58:59 INFO - _destroyToolbox@resource://devtools/client/framework/toolbox.js:3745:27
[task 2020-07-04T00:58:59.159Z] 00:58:59 INFO - destroy@resource://devtools/client/framework/toolbox.js:3615:10
[task 2020-07-04T00:58:59.159Z] 00:58:59 INFO - _endRemoveTab@chrome://browser/content/tabbrowser.js:3697:15
[task 2020-07-04T00:58:59.159Z] 00:58:59 INFO - removeTab@chrome://browser/content/tabbrowser.js:3342:14
[task 2020-07-04T00:58:59.159Z] 00:58:59 INFO - removeTab@chrome://mochitests/content/browser/devtools/client/shared/test/shared-head.js:371:12
[task 2020-07-04T00:58:59.159Z] 00:58:59 INFO - toolboxTestScript/<@chrome://mochitests/content/browser/devtools/client/aboutdebugging/test/browser/browser_aboutdebugging_addons_debug_inspector.js:95:26
[task 2020-07-04T00:58:59.159Z] 00:58:59 INFO - process@resource://gre/modules/Promise-backend.js:961:38
[task 2020-07-04T00:58:59.159Z] 00:58:59 INFO - walkerLoop@resource://gre/modules/Promise-backend.js:845:29
[task 2020-07-04T00:58:59.159Z] 00:58:59 INFO - Promise*scheduleWalkerLoop@resource://gre/modules/Promise-backend.js:775:19
[task 2020-07-04T00:58:59.159Z] 00:58:59 INFO - schedulePromise@resource://gre/modules/Promise-backend.js:809:12
[task 2020-07-04T00:58:59.159Z] 00:58:59 INFO - completePromise@resource://gre/modules/Promise-backend.js:741:12
[task 2020-07-04T00:58:59.159Z] 00:58:59 INFO - Rejection date: Sat Jul 04 2020 00:58:58 GMT+0000 (Greenwich Mean Time) - false == true - JS frame :: resource://testing-common/PromiseTestUtils.jsm :: assertNoUncaughtRejections :: line 265
[task 2020-07-04T00:58:59.159Z] 00:58:59 INFO - Stack trace:
[task 2020-07-04T00:58:59.159Z] 00:58:59 INFO - resource://testing-common/PromiseTestUtils.jsm:assertNoUncaughtRejections:265
[task 2020-07-04T00:58:59.159Z] 00:58:59 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1095
[task 2020-07-04T00:58:59.159Z] 00:58:59 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1104
[task 2020-07-04T00:58:59.159Z] 00:58:59 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:927
[task 2020-07-04T00:58:59.159Z] 00:58:59 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:1029
[task 2020-07-04T00:58:59.160Z] 00:58:59 INFO - Leaving test bound testWebExtensionsToolboxWebConsole
[task 2020-07-04T00:58:59.160Z] 00:58:59 INFO - TEST-PASS | devtools/client/aboutdebugging/test/browser/browser_aboutdebugging_addons_debug_inspector.js | The main process DevToolsServer has no pending connection when the test ends -
[task 2020-07-04T00:58:59.200Z] 00:58:59 INFO - GECKO(5328) | MEMORY STAT | vsize 2104459MB | vsizeMaxContiguous 65030096MB | residentFast 447MB | heapAllocated 173MB
[task 2020-07-04T00:58:59.200Z] 00:58:59 INFO - TEST-OK | devtools/client/aboutdebugging/test/browser/browser_aboutdebugging_addons_debug_inspector.js | took 8896ms
[task 2020-07-04T00:58:59.200Z] 00:58:59 INFO - GECKO(5328) | [Child 2308: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 0000029FC3B41800 == 1 [pid = 2308] [id = {c14e6b65-ec95-4433-bd66-1ea50acda699}]
[task 2020-07-04T00:58:59.200Z] 00:58:59 INFO - GECKO(5328) | [Child 2308: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (0000029FCA855090) [pid = 2308] [serial = 8] [outer = 0000000000000000]
[task 2020-07-04T00:58:59.200Z] 00:58:59 INFO - GECKO(5328) | [Child 2308: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 3 (0000029FC9EAC400) [pid = 2308] [serial = 9] [outer = 0000029FCA855090]
[task 2020-07-04T00:58:59.226Z] 00:58:59 INFO - GECKO(5328) | [Child 2308: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 4 (0000029FCA874C00) [pid = 2308] [serial = 10] [outer = 0000029FCA855090]
[task 2020-07-04T00:58:59.226Z] 00:58:59 INFO - checking window state
[task 2020-07-04T00:58:59.266Z] 00:58:59 INFO - TEST-START | devtools/client/aboutdebugging/test/browser/browser_aboutdebugging_addons_debug_nobg.js
Comment hidden (Intermittent Failures Robot) |
Comment 2•4 years ago
|
||
Julian, any insight what started this late on Friday (European time)? https://hg.mozilla.org/integration/autoland/log?rev=devtools
Assignee | ||
Comment 3•4 years ago
|
||
I think the first autoland changeset that recorded the failure (bug 1640338) could explain the increased frequency. It might have improved the startup time of a few panels, leading the test to close the toolbox earlier while some pending requests didn't fully resolve.
Toolbox open relies on a few server side calls which are not properly await
ed for.
https://searchfox.org/mozilla-central/rev/c86c19bd64f8f19590a4190c282781d3a9631422/devtools/client/framework/toolbox.js#872
this._buildTabs();
this._applyCacheSettings();
Both methods are async and should be prefixed by await to make toolbox open properly wait on everything.
Or we need to wrap them with the newly added safeAsyncMethod
helper.
Assignee | ||
Comment 4•4 years ago
|
||
Assignee | ||
Comment 5•4 years ago
|
||
When switching from a dedicated addon toolbox to an about:devtools-toolbox tab, we did a minimal migration for the browser_aboutdebugging_addons_debug_* tests.
They used to inject a "toolbox test script" in the process of the addon toolbox. But we could have updated them with regular test APIs, async/await patterns etc.
Doing the migration now in preparation for adding calls to waitForRequestsToSettle in the next changeset.
Updated•4 years ago
|
Assignee | ||
Comment 6•4 years ago
|
||
Depends on D82362
Comment hidden (Intermittent Failures Robot) |
Pushed by jdescottes@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/ffab9fce88d6 Rewrite browser_aboutdebugging_addons_debug_* using regular test APIs r=daisuke https://hg.mozilla.org/integration/autoland/rev/4239c501d542 Wait for requests to settle in all browser_aboutdebugging_addons_debug_* tests r=daisuke
Comment 9•4 years ago
|
||
bugherder |
https://hg.mozilla.org/mozilla-central/rev/ffab9fce88d6
https://hg.mozilla.org/mozilla-central/rev/4239c501d542
Comment hidden (Intermittent Failures Robot) |
Description
•