Closed Bug 1165482 Opened 9 years ago Closed 9 years ago

Intermittent browser_toolbar_basic.js | A promise chain failed to handle a rejection: - Unable to attach to the console

Categories

(DevTools :: General, defect)

Product:
DevTools
Component:
General
Platform:
x86
Linux
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(firefox39 unaffected, firefox40 wontfix, firefox41 fixed, firefox-esr31 unaffected, firefox-esr38 unaffected)

Status:
RESOLVED FIXED
Milestone:
Firefox 41
Tracking Flags:
Tracking Status
firefox39 --- unaffected
firefox40 --- wontfix
firefox41 --- fixed
firefox-esr31 --- unaffected
firefox-esr38 --- unaffected

People

(Reporter: RyanVM, Assigned: sjakthol)

Details

(Keywords: intermittent-failure)

Attachments

(1 file, 1 obsolete file)

bug-1165482-toolbar-catch-expected-rejections.patch
1.80 KB, patch
sjakthol
: review+
Details | Diff | Splinter Review 
11:42:57 INFO - 4857 INFO TEST-START | browser/devtools/shared/test/browser_toolbar_basic.js
11:43:00 INFO - 4858 INFO checking window state
11:43:00 INFO - 4859 INFO Starting browser_toolbar_basic.js
11:43:00 INFO - 4860 INFO TEST-PASS | browser/devtools/shared/test/browser_toolbar_basic.js | DeveloperToolbar is not visible in runTest
11:43:00 INFO - 4861 INFO TEST-PASS | browser/devtools/shared/test/browser_toolbar_basic.js | DeveloperToolbar is visible in checkOpen
11:43:00 INFO - 4862 INFO TEST-PASS | browser/devtools/shared/test/browser_toolbar_basic.js | Close button exists
11:43:00 INFO - 4863 INFO TEST-PASS | browser/devtools/shared/test/browser_toolbar_basic.js | toggle toolbox button is not checked
11:43:00 INFO - 4864 INFO Console message: [JavaScript Warning: "Error in parsing value for 'text-anchor'. Declaration dropped." {file: "resource://gre/modules/devtools/server/actors/highlighter.css" line: 272 column: 15 source: " text-anchor: left;"}]
11:43:00 INFO - 4865 INFO TEST-PASS | browser/devtools/shared/test/browser_toolbar_basic.js | toggle toolbox button is checked
11:43:00 INFO - 4866 INFO Opened a new tab
11:43:00 INFO - 4867 INFO TEST-PASS | browser/devtools/shared/test/browser_toolbar_basic.js | toggle toolbox button is not checked
11:43:00 INFO - 4868 INFO TEST-PASS | browser/devtools/shared/test/browser_toolbar_basic.js | DeveloperToolbar is not visible in checkClosed
11:43:00 INFO - 4869 INFO TEST-PASS | browser/devtools/shared/test/browser_toolbar_basic.js | DeveloperToolbar is visible in checkReOpen
11:43:00 INFO - 4870 INFO TEST-PASS | browser/devtools/shared/test/browser_toolbar_basic.js | toggle toolbox button is checked
11:43:00 INFO - 4871 INFO TEST-PASS | browser/devtools/shared/test/browser_toolbar_basic.js | DeveloperToolbar is not visible in checkReClosed
11:43:00 INFO - 4872 INFO TEST-UNEXPECTED-FAIL | browser/devtools/shared/test/browser_toolbar_basic.js | A promise chain failed to handle a rejection: - Unable to attach to the console
11:43:00 INFO - Stack trace:
11:43:00 INFO - JS frame :: resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js :: PendingErrors.register :: line 162
11:43:00 INFO - JS frame :: resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js :: this.PromiseWalker.completePromise :: line 675
11:43:00 INFO - JS frame :: resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js :: Handler.prototype.process :: line 903
11:43:00 INFO - JS frame :: resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js :: this.PromiseWalker.walkerLoop :: line 746
11:43:00 INFO - JS frame :: resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js :: this.PromiseWalker.scheduleWalkerLoop/< :: line 688
11:43:00 INFO - native frame :: <unknown filename> :: <TOP_LEVEL> :: line 0
11:43:00 INFO - testScope/test_finish/<@chrome://mochikit/content/browser-test.js:1049:11
11:43:00 INFO - testScope/test_executeSoon/<.run@chrome://mochikit/content/browser-test.js:951:9
11:43:00 INFO - MEMORY STAT vsize after test: 738066432
11:43:00 INFO - MEMORY STAT residentFast after test: 209022976
11:43:00 INFO - MEMORY STAT heapAllocated after test: 93096548
11:43:00 INFO - 4873 INFO TEST-OK | browser/devtools/shared/test/browser_toolbar_basic.js | took 3572ms
Joe, can you please help me find an owner for this frequent failure?
Flags: needinfo?(jwalker)
This test adds a new tab that makes the developer toolbar to update its state which results into a call to makeRemote on the new tab target (at [1]). However, immediately after the tab is created, the test closes it.

Now, if the makeRemote managed to attach the console before that, everything is fine. But in some cases, the server destroys the actors before makeRemote gets to the part in which it tries to attach the console and fails (the actual error returned by the server is 'No such actor for ID: <something>').

This patch suppresses the specific case of [1] rejecting when the tab has been closed during the operation. Other errors are still propagated as they might indicate real issues though this can be easily changed.

Try: https://treeherder.mozilla.org/#/jobs?repo=try&revision=6793a938b5fc

[1] https://dxr.mozilla.org/mozilla-central/source/browser/devtools/shared/DeveloperToolbar.jsm#649
Assignee: nobody → sjakthol
Status: NEW → ASSIGNED
Flags: needinfo?(jwalker)
Attachment #8609735 - Flags: review?(bgrinstead)
Comment on attachment 8609735 [details] [diff] [review]
bug-1165482-toolbar-catch-expected-rejections.patch

Review of attachment 8609735 [details] [diff] [review]:
-----------------------------------------------------------------

I've been unable to reproduce locally.  But this seems generally sane, so r=me with the minor updates listed.

My main concern is making sure that we don't end up in a situation where releaseSystem never gets called and we ended up with linksForTarget with an extra reference that never got removed here https://dxr.mozilla.org/mozilla-central/source/toolkit/devtools/gcli/commands/index.js#157.  This particular error is caused due to: `getSystem -> GcliFront.create -> target.makeRemote -> reject`, so in this case I don't think it's going to be a problem (releaseSystem will happen when the dev toolbar is closed, regardless of whether it's successfully opened).

::: browser/devtools/shared/DeveloperToolbar.jsm
@@ +650,4 @@
>        gcliInit.getSystem(this.target).then(system => {
>          this.requisition.system = system;
> +      }, error => {
> +        if (this._chromeWindow.gBrowser.getBrowserForTab(tab) === null) {

You can just check `!this._chromeWindow.gBrowser.getBrowserForTab(tab)`

@@ +652,5 @@
> +      }, error => {
> +        if (this._chromeWindow.gBrowser.getBrowserForTab(tab) === null) {
> +          // The tab was closed, suppress the error and print a warning as the
> +          // destroyed tab was likely the cause.
> +          console.warn("An error occurred as the tab was closed while " +

Please wrap these into a single console.warn call with error passed in as a second argument
Attachment #8609735 - Flags: review?(bgrinstead) → review+
(In reply to Brian Grinstead [:bgrins] from comment #53)
> My main concern is making sure that we don't end up in a situation where
> releaseSystem never gets called and we ended up with linksForTarget with an
> extra reference that never got removed here
> https://dxr.mozilla.org/mozilla-central/source/toolkit/devtools/gcli/
> commands/index.js#157.  This particular error is caused due to: `getSystem
> -> GcliFront.create -> target.makeRemote -> reject`, so in this case I don't
> think it's going to be a problem (releaseSystem will happen when the dev
> toolbar is closed, regardless of whether it's successfully opened).

Actually, now that I looked closer the refcounting is very broken with or without this patch.

The refcount is increased every time getSystem is called. So for every 'TabSelected' or 'load' event the refcount is increased by one. However, releaseSystem is only called once when the the toolbar is destroyed meaning if you're actually doing anything while Developer Toolbar is open, the resources won't be released correctly.

Filed this as bug 1168679.
Updated the patch to address comments.
Attachment #8609735 - Attachment is obsolete: true
Attachment #8610953 - Flags: review+
Keywords: checkin-needed
https://hg.mozilla.org/mozilla-central/rev/29560af16777
Status: ASSIGNED → RESOLVED
Closed: 9 years ago
status-firefox41: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 41
Sami, is this something we should consider backporting?
status-firefox39: --- → ?
status-firefox40: --- → ?
status-firefox-esr31: --- → unaffected
status-firefox-esr38: --- → ?
Flags: needinfo?(sjakthol)
Like the other bug this only affects aurora and happens during testing and doesn't affect user experience in any way. As this seem to be e10s only (though it could happen in non e10s but e10s is just that bit slower to make the rejection manifest itself more often) I'd say wontfix like the other one.
status-firefox39: ? → unaffected
status-firefox40: ? → wontfix
status-firefox-esr38: ? → unaffected
Flags: needinfo?(sjakthol)
Thanks :)
Product: Firefox → DevTools
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: