Closed Bug 1650510 Opened 4 years ago Closed 4 years ago

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)

defect

Tracking

(firefox80 fixed)

RESOLVED FIXED
Firefox 80
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

Julian, any insight what started this late on Friday (European time)? https://hg.mozilla.org/integration/autoland/log?rev=devtools

Flags: needinfo?(jdescottes)

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 awaited 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.

Flags: needinfo?(jdescottes)

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.

Assignee: nobody → jdescottes
Status: NEW → ASSIGNED
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
Status: ASSIGNED → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 80
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: