Closed Bug 1268073 Opened 8 years ago Closed 8 years ago

Misleading error if you click "Debug" twice

Categories

(DevTools :: about:debugging, defect, P3)

Product:
DevTools
Component:
about:debugging
Type:
defect

Tracking

(firefox49 affected, firefox50 verified)

Status:
VERIFIED FIXED
Milestone:
Firefox 50
Tracking Flags:
Tracking Status
firefox49 --- affected
firefox50 --- verified

People

(Reporter: wbamberg, Assigned: jyeh, Mentored)

Details

(Whiteboard: [good taipei bug])

Attachments

(4 files, 4 obsolete files)

Misleading error if you click "Debug" twice
2.84 KB, patch
janx
: review+
Details | Diff | Splinter Review
Fix a few BrowserToolboxProcess leaks.
1.31 KB, patch
ochameau
: review+
Details | Diff | Splinter Review
Prevent leaking BrowserToolboxProcess instance when debuggerServer leaks.
1.83 KB, patch
jryans
: review+
Details | Diff | Splinter Review
Free loader created by BrowserToolboxProcess.
2.36 KB, patch
jryans
: review+
Details | Diff | Splinter Review 
If you open about:debugging, then click the "Debug" button next to an add-on, then the Add-on Debugger opens. If you click the button again (maybe because you forgot you'd clicked it, and the Debugger window was hidden) you get this message (on OS X):

"Close Firefox

A copy of Firefox is already open. Only one copy of Firefox can be open at a time."

Or this (On Linux):

"Firefox is already running, but is not responding. To open a new window, you must first close the existing Firefox process, or restart your system."

This is confusing to people who don't think of the Add-on Debugger as a copy of Firefox.
The message you get on Windows is:

"Firefox is already running, but is not responding. The old Firefox process must be closed to open a new window."

Besides the message itself being confusing for some people, I am wondering why it differs on the different OSs.

Sebastian
OS: Unspecified → All
Hardware: Unspecified → All
Thanks for reporting this bug!

Instead of showing this message (or trying to open a second toolbox), we should probably just focus an already open toolbox.

I'm not sure how easy this is to do for a BrowserToolbox (what Add-on debugging uses today), but maybe this is possible for "about:devtools-toolbox" URLs (what Add-on debugging should use after bug 1243460 is fixed).

Alex, is there any way to make "about:devtools-toolbox" links open an already existing toolbox tab instead of opening a new one on every click?
Flags: needinfo?(poirot.alex)
Priority: -- → P3
I'm not sure we will be able to use about:devtools-toolbox URLs for addons. I think addons toolbox has to stay in a distinct process.

We should somehow not launch another process and somehow communicate with that process to focus the window. Not trivial.
At the very least, about:debugging could use BrowserToolboxProcess arguments (onClose/onRun) to figure out when a toolbox is already open:
http://mxr.mozilla.org/mozilla-central/source/devtools/client/framework/ToolboxProcess.jsm#29
And prevent trying to open another one!
Flags: needinfo?(poirot.alex)
The goal of this bug is to keep track of every BrowserToolboxProcess we open when debugging an Add-on from about:debugging#addons, in order to prevent trying to open a second BrowserToolboxProcess if a first one is still open.

Additionally, it would be nice to find a way to focus the already-open toolbox when the user clicks on the "Debug" button again in about:debugging#addons.

In comment 3, Alex suggests using BrowserToolboxProcess arguments (onClose/onRun), and the code responsible for launching BrowserToolboxProcesses lives in AddonTarget.debug()[0].

[0] https://dxr.mozilla.org/mozilla-central/source/devtools/client/aboutdebugging/components/addons/target.js#25
Mentor: janx
Whiteboard: [good taipei bug]
Hi Jan, I'd like to try this bug :)
Assignee: nobody → jyeh
Hi Joseph, very cool thank you! Please ask any questions if something isn't clear. Me or Alex are always happy to help :)
Status: NEW → ASSIGNED
Hi Jan,

This patch is my first try, might need some of your feedback :)

I found out that 'onRun' was triggered after the BrowserToolboxProcess has already been created.

http://mxr.mozilla.org/mozilla-central/source/devtools/client/framework/ToolboxProcess.jsm#232

So we cannot prevent the BrowserToolboxProcess launching another process with the 'onRun' function.

In my patch, I simply just return the BrowserToolboxProcess.init function if there is already a process running. This will stop launching another process and therefore the confusing message will not popup.

However, it seems a little strange if we do not show any message to the user. Because the current running process may not be the same as the user has clicked on.

I also couldn’t find the way to focus toolbox, can you guide me the way :(

Thanks!
Attachment #8755367 - Flags: feedback?(janx)
Hi Joseph, thanks a lot for the patch! I'll have a look now.
Comment on attachment 8755367 [details] [diff] [review]
0001-Bug-1268073-Misleading-error-if-you-click-Debug-twice.patch

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

Thanks again for working on this!

Your patch works, but I think there is a better way to fix the problem:

When a BrowserToolboxProcess is already open, and the user clicks on a "Debug" button again in about:debugging#addons, your change successfully prevents the "Firefox is already running" prompt from showing up. However, I think that the new behavior (doing nothing when the user clicks on a "Debug" button) is still confusing to users.

Instead, maybe we can save the result of `BrowserToolboxProcess.init()`, in order to only allow one open Add-on Toolbox from about:debugging#addons?

Then if a Toolbox is already open for an Add-on, we can decide to either:
1) Disable all "Debug" buttons in the `AddonsPanel` component until that toolbox is closed,
2) Or we could leave all "Debug" buttons enabled, but if the user clicks on any of them, call `.close()` any pre-existing Toolbox before opening a new one

I think the best way to implement this would be to create an `addon.js` module, similar to `worker.js` [0], with a `debugAddon()` method. This method would call `BrowserToolboxProcess.init()` (or the equivalent `new BrowserToolboxProcess()`), keep track of any open Toolbox, and either 1) tell `AddonsPanel` to disable all Add-ons when a Toolbox is open, or 2) simply close any existing Toolbox before opening a new one.

I think I prefer 2) because it is simpler.

The `AddonTarget` component would then be able to import the new module, and call `debugAddon()` whenever a "Debug" button is clicked [1].

[0] https://dxr.mozilla.org/mozilla-central/source/devtools/client/aboutdebugging/modules/worker.js
[1] https://dxr.mozilla.org/mozilla-central/source/devtools/client/aboutdebugging/components/addons/target.js#25
Attachment #8755367 - Flags: feedback?(janx)
Joseph, please let me know what you think of my suggested solution, and if you have any questions regarding how to implement it.
Flags: needinfo?(jyeh)
I think option 2 makes sense to me. Actually I already try it once but did not apply to my first patch :P

I'll provide the updated patch later, thanks for your advice!
Flags: needinfo?(jyeh)
Attachment #8755751 - Flags: review?(janx)
Comment on attachment 8755751 [details]
Bug 1268073 - Misleading error if you click "Debug" twice;

https://reviewboard.mozilla.org/r/54792/#review51766

F+ (not sure how to indicate this within MozReview).

Your patch looks great and works great (and all tests seem to pass for me). However, I have one last worry: I would prefer that we don't kill any open BrowserToolboxProcesses that were not created by about:debugging. Here are some suggestions on how to do that (and which don't require any changes to BrowserToolboxProcess itself).

::: devtools/client/aboutdebugging/modules/addon.js:11
(Diff revision 1)
> +
> +loader.lazyImporter(this, "BrowserToolboxProcess",
> +  "resource://devtools/client/framework/ToolboxProcess.jsm");
> +
> +exports.debugAddon = function (addonID) {
> +  const processes = BrowserToolboxProcess.getProcesses();

Nit: Instead of closing all pre-existing BrowserToolboxProcesses, I would prefer if we only ever kill toolboxes that came from about:debugging (e.g. if you opened a Browser Toolbox from Firefox directly, I would expect about:debugging not to close that toolbox).

Could you please save the result of `BrowserToolboxProcess.init()` in a global (e.g. `toolbox = B.init()`), so that we can call `.close()` on that global if there are any future calls to `debugAddon()`? (You can then also reset the global to `null` when the user closes manually the toolbox, by means of a `onClose` function).

::: devtools/client/framework/ToolboxProcess.jsm:98
(Diff revision 1)
> + * Get all running processes.
> + * @return object
> + */
> +BrowserToolboxProcess.getProcesses = function() {
> +  return processes;
> +};

Nit: I would prefer if we can avoid changing the BrowserToolboxProcess API. If you follow my previous suggestion, adding this `getProcesses()` method won't be necessary anymore.
Comment on attachment 8755367 [details] [diff] [review]
0001-Bug-1268073-Misleading-error-if-you-click-Debug-twice.patch

(Marking the older patch as obsolete.)
Attachment #8755367 - Attachment is obsolete: true
Comment on attachment 8755751 [details]
Bug 1268073 - Misleading error if you click "Debug" twice;

(Setting F+ on the attachment directly since MozReview didn't seem to know how to do this.)
Attachment #8755751 - Flags: feedback+
Note: Since we're getting close to R+, please send your next patch to try and paste the treeherder link here, just to make sure all tests continue to pass on each platform.
Comment on attachment 8755751 [details]
Bug 1268073 - Misleading error if you click "Debug" twice;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/54792/diff/1-2/
Attachment #8755751 - Flags: feedback+ → review?(janx)
Here's the treeherder link:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=4c8a7d4e1f34

I'm not sure if I do this correctly :/
Attachment #8755751 - Flags: review?(janx)
Comment on attachment 8755751 [details]
Bug 1268073 - Misleading error if you click "Debug" twice;

https://reviewboard.mozilla.org/r/54792/#review54710

R+ with one nit. Thanks a lot Joseph!

Please address the remaining nit, and re-send your patch to try. Your previous treeherder link was great, but you seem to hit the intermittent bug 1268178 suprizingly often. I'd like to see if that problem became what we call a "top orange" or a "perma-fail".

::: devtools/client/aboutdebugging/modules/addon.js:10
(Diff revision 2)
> +"use strict";
> +
> +loader.lazyImporter(this, "BrowserToolboxProcess",
> +  "resource://devtools/client/framework/ToolboxProcess.jsm");
> +
> +let toolbox;

Nit: Please initialize to `let toolbox = null`.
Attachment #8755751 - Flags: review+
(Also setting needinfo just so you're aware of my reply. Sorry that it took so long, I was away for a while but now I'm back.)
Flags: needinfo?(jyeh)
Comment on attachment 8755751 [details]
Bug 1268073 - Misleading error if you click "Debug" twice;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/54792/diff/2-3/
Attachment #8755751 - Attachment description: MozReview Request: Bug 1268073 - Misleading error if you click "Debug" twice; r?janx → Bug 1268073 - Misleading error if you click "Debug" twice;
Attachment #8755751 - Flags: review+ → review?(janx)
Thanks Jan, treeherder looks better this time.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=09313419cdfe
Flags: needinfo?(jyeh)
Comment on attachment 8755751 [details]
Bug 1268073 - Misleading error if you click "Debug" twice;

Thanks Joseph!

I'm not sure why, but your patch seems to cause the test browser_addons_debug_bootstrapped.js to leak two "about:debugging#addons" windows (see orange results on debug builds).

Maybe you're forgetting to clean up something properly on shutdown? I'm not sure what. Alex, do you see any obvious leaks in Joseph's patch or in the test[0]?

[0] https://dxr.mozilla.org/mozilla-central/source/devtools/client/aboutdebugging/test/browser_addons_debug_bootstrapped.js

---

03:15:47  WARNING -  TEST-UNEXPECTED-FAIL | devtools/client/aboutdebugging/test/browser_addons_debug_bootstrapped.js | leaked 2 window(s) until shutdown [url = about:debugging#addons]
03:15:47     INFO -  TEST-INFO | devtools/client/aboutdebugging/test/browser_addons_debug_bootstrapped.js | windows(s) leaked: [pid = 1869] [serial = 23], [pid = 1869] [serial = 25]

The two windows are:

03:15:47     INFO -  --DOMWINDOW == 11 (0x97174800) [pid = 1869] [serial = 23] [outer = (nil)] [url = about:debugging#addons]
03:15:47     INFO -  --DOMWINDOW == 10 (0x95ceb000) [pid = 1869] [serial = 25] [outer = (nil)] [url = about:debugging#addons]
Flags: needinfo?(poirot.alex)
Attachment #8755751 - Flags: review?(janx)
https://reviewboard.mozilla.org/r/54792/#review55064

::: devtools/client/aboutdebugging/modules/addon.js:10
(Diff revision 3)
> +"use strict";
> +
> +loader.lazyImporter(this, "BrowserToolboxProcess",
> +  "resource://devtools/client/framework/ToolboxProcess.jsm");
> +
> +let toolbox = null;

If toolbox isn't cleared as expected, this may introduce a leak.
Did you verified onClose was always called? May be on browser_addons_debug_bootstrapped.js, it isn't? Or it is called, but too late, after the test is finished?
Flags: needinfo?(poirot.alex)
(In reply to Alexandre Poirot [:ochameau] from comment #24)
> https://reviewboard.mozilla.org/r/54792/#review55064
> 
> ::: devtools/client/aboutdebugging/modules/addon.js:10
> (Diff revision 3)
> > +"use strict";
> > +
> > +loader.lazyImporter(this, "BrowserToolboxProcess",
> > +  "resource://devtools/client/framework/ToolboxProcess.jsm");
> > +
> > +let toolbox = null;
> 
> If toolbox isn't cleared as expected, this may introduce a leak.
> Did you verified onClose was always called? May be on
> browser_addons_debug_bootstrapped.js, it isn't? Or it is called, but too
> late, after the test is finished?

Thanks for your suggestion Alex!

If you edit the test browser_addons_debug_bootstrapped.js so as to not open a toolbox, nor expect a custom message, the leaks disappear.

However, it seems that `onClose` is really called (but maybe too late?). Here is the full annotated log of the test that started leaking ([...] means irrelevant content was snipped out):

> runtests.py | Running with e10s: True
> [...]
> 1 INFO checking window state
> ++DOCSHELL 0x7f51c7ef5000 == 7 [pid = 28020] [id = 7]
> ++DOMWINDOW == 16 (0x7f51c7c31000) [pid = 28020] [serial = 16] [outer = (nil)]
> ++DOMWINDOW == 17 (0x7f51c7c36400) [pid = 28020] [serial = 17] [outer = 0x7f51c7c31000]
> [Child 28117] WARNING: '!compMgr', file /home/user/firefox/xpcom/glue/nsComponentManagerUtils.cpp, line 63
> 2 INFO TEST-START | devtools/client/aboutdebugging/test/browser_addons_debug_bootstrapped.js
> 3 INFO Entering test bound 
> ++DOMWINDOW == 18 (0x7f51c7cee400) [pid = 28020] [serial = 18] [outer = 0x7f51c7c31000]
> 4 INFO opening about:debugging
> 5 INFO Adding tab: about:debugging#addons
> ++DOCSHELL 0x7f51c6f80000 == 8 [pid = 28020] [id = 8]
> ++DOMWINDOW == 19 (0x7f51c7cfa800) [pid = 28020] [serial = 19] [outer = (nil)]
> ++DOMWINDOW == 20 (0x7f51c7cfd400) [pid = 28020] [serial = 20] [outer = 0x7f51c7cfa800]
> ++DOMWINDOW == 21 (0x7f51de736400) [pid = 28020] [serial = 21] [outer = 0x7f51c7cfa800]
> [Child 28117] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file /home/user/firefox/toolkit/xre/nsXREDirProvider.cpp, line 1476
> [Parent 28020] WARNING: GetDefaultCharsetForLocale: need to add multi locale support: file /home/user/firefox/intl/locale/unix/nsUNIXCharset.cpp, line 98
> 6 INFO Tab added and finished loading: about:debugging#addons
> 7 INFO Waiting for add-ons to load. Current add-on count: 0
> 8 INFO TEST-PASS | devtools/client/aboutdebugging/test/browser_addons_debug_bootstrapped.js | Addon installed and running its bootstrap.js file - 
> 9 INFO TEST-PASS | devtools/client/aboutdebugging/test/browser_addons_debug_bootstrapped.js | The addon name appears in the list of addons: Firefox Hello,IndexedDBTest,Mochitest,mozscreenshots,Multi-process staged rollout,Pocket,Special Powers,test-devtools,Web Compat,WorkerTestBootstrap - 
> 10 INFO TEST-PASS | devtools/client/aboutdebugging/test/browser_addons_debug_bootstrapped.js | Found the addon in the list - 
> 11 INFO TEST-PASS | devtools/client/aboutdebugging/test/browser_addons_debug_bootstrapped.js | Found its debug button - 

Here `toolbox` is created:

> #### toolbox = BrowserToolboxProcess.init() ####
> ++DOCSHELL 0x7f3e8f4b7800 == 1 [pid = 28117] [id = 1]
> ++DOCSHELL 0x7f51ca645800 == 9 [pid = 28020] [id = 9]
> ++DOMWINDOW == 22 (0x7f51ca646000) [pid = 28020] [serial = 22] [outer = (nil)]
> ++DOMWINDOW == 23 (0x7f51c5b58000) [pid = 28020] [serial = 23] [outer = 0x7f51ca646000]
> ++DOMWINDOW == 1 (0x7f3e8df0d000) [pid = 28117] [serial = 1] [outer = (nil)]
> ++DOMWINDOW == 24 (0x7f51c61d1800) [pid = 28020] [serial = 24] [outer = 0x7f51ca646000]
> ++DOCSHELL 0x7f51c61d4000 == 10 [pid = 28020] [id = 10]
> ++DOMWINDOW == 25 (0x7f51c5192000) [pid = 28020] [serial = 25] [outer = (nil)]
> ++DOMWINDOW == 26 (0x7f51cea23400) [pid = 28020] [serial = 26] [outer = 0x7f51c5192000]
> [Parent 28020] WARNING: Could not get disk status from nsIDiskSpaceWatcher: file /home/user/firefox/uriloader/prefetch/nsOfflineCacheUpdateService.cpp, line 283
> ++DOMWINDOW == 2 (0x7f3e8de69400) [pid = 28117] [serial = 2] [outer = 0x7f3e8df0d000]
> [28167] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file /home/user/firefox/extensions/cookie/nsPermissionManager.cpp, line 2630
> ++DOCSHELL 0x7f3894ee5800 == 1 [pid = 28167] [id = 1]
> ++DOMWINDOW == 1 (0x7f3894ee6000) [pid = 28167] [serial = 1] [outer = (nil)]
> ++DOMWINDOW == 2 (0x7f3894ee7000) [pid = 28167] [serial = 2] [outer = 0x7f3894ee6000]
> --DOCSHELL 0x7f51d0074000 == 9 [pid = 28020] [id = 5]
> ++DOCSHELL 0x7f389203a000 == 2 [pid = 28167] [id = 2]
> ++DOMWINDOW == 3 (0x7f38920ba800) [pid = 28167] [serial = 3] [outer = (nil)]
> ++DOMWINDOW == 4 (0x7f38920bb800) [pid = 28167] [serial = 4] [outer = 0x7f38920ba800]
> ++DOMWINDOW == 5 (0x7f38952e1000) [pid = 28167] [serial = 5] [outer = 0x7f3894ee6000]
> [28167] WARNING: Hardware Vsync support not yet implemented. Falling back to software timers: file /home/user/firefox/gfx/thebes/gfxPlatform.cpp, line 2243
> JavaScript error: resource://gre/modules/XPCOMUtils.jsm, line 191: TypeError: can't redefine non-configurable property "Services"
> ++DOCSHELL 0x7f3885e9a800 == 3 [pid = 28167] [id = 3]
> ++DOMWINDOW == 6 (0x7f3885e9b000) [pid = 28167] [serial = 6] [outer = (nil)]
> ++DOMWINDOW == 7 (0x7f3885e9d000) [pid = 28167] [serial = 7] [outer = 0x7f3885e9b000]
> [28167] WARNING: Failed to retarget HTML data delivery to the parser thread.: file /home/user/firefox/parser/html/nsHtml5StreamParser.cpp, line 967
> [28167] WARNING: 'NS_FAILED(rv)', file /home/user/firefox/dom/base/URL.cpp, line 96
> ++DOMWINDOW == 8 (0x7f3883be7000) [pid = 28167] [serial = 8] [outer = 0x7f3885e9b000]
> ++DOCSHELL 0x7f3883d58000 == 4 [pid = 28167] [id = 4]
> ++DOMWINDOW == 9 (0x7f3883d58800) [pid = 28167] [serial = 9] [outer = (nil)]
> ++DOMWINDOW == 10 (0x7f3883d59800) [pid = 28167] [serial = 10] [outer = 0x7f3883d58800]
> Chrome file doesn't exist: /home/user/firefox/obj-x86_64-pc-linux-gnu/dist/bin/browser/chrome/devtools/content/debugger/views/sources-view.js
> Failed to load file:///home/user/firefox/obj-x86_64-pc-linux-gnu/dist/bin/browser/chrome/devtools/content/debugger/views/sources-view.js
> Chrome file doesn't exist: /home/user/firefox/obj-x86_64-pc-linux-gnu/dist/bin/browser/chrome/devtools/content/debugger/views/event-listeners-view.js
> Failed to load file:///home/user/firefox/obj-x86_64-pc-linux-gnu/dist/bin/browser/chrome/devtools/content/debugger/views/event-listeners-view.js
> ++DOCSHELL 0x7f38820c7800 == 5 [pid = 28167] [id = 5]
> ++DOMWINDOW == 11 (0x7f38820c8000) [pid = 28167] [serial = 11] [outer = (nil)]
> ++DOMWINDOW == 12 (0x7f38820df800) [pid = 28167] [serial = 12] [outer = 0x7f38820c8000]
> ++DOCSHELL 0x7f3880d7e000 == 6 [pid = 28167] [id = 6]
> ++DOMWINDOW == 13 (0x7f3880d7e800) [pid = 28167] [serial = 13] [outer = (nil)]
> ++DOMWINDOW == 14 (0x7f3880d7f800) [pid = 28167] [serial = 14] [outer = 0x7f3880d7e800]
> [28167] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004001: file /home/user/firefox/dom/xul/nsXULPrototypeCache.cpp, line 326
> [28167] WARNING: 'NS_FAILED(rv)', file /home/user/firefox/dom/base/URL.cpp, line 96

Here the custom function is executed in the toolbox, calling `toolbox.destroy()`:

> #### jsterm.execute() ####
> 12 INFO TEST-PASS | devtools/client/aboutdebugging/test/browser_addons_debug_bootstrapped.js | Received the notification message from the bootstrap.js function - 
> #### toolbox.destroy() ####
> --DOCSHELL 0x7f389203a000 == 5 [pid = 28167] [id = 2]

(Is this relevant?):

> [28167] WARNING: An event was posted to a thread that will never run it (rejected): file /home/user/firefox/xpcom/threads/nsThread.cpp, line 656
> [28167] WARNING: unable to post continuation event: file /home/user/firefox/xpcom/io/nsStreamUtils.cpp, line 480
> ]: [28167] WARNING: NS_ENSURE_TRUE(maybeContext) failed: file /home/user/firefox/xpcom/threads/nsThread.cpp, line 887
> [28167] WARNING: 'NS_FAILED(RemovePermissionChangeObserver())', file /home/user/firefox/dom/notification/Notification.cpp, line 692

Here it looks like a lot of windows are getting closed:

> --DOCSHELL 0x7f38820c7800 == 4 [pid = 28167] [id = 5]
> --DOCSHELL 0x7f3894ee5800 == 3 [pid = 28167] [id = 1]
> --DOCSHELL 0x7f3880d7e000 == 2 [pid = 28167] [id = 6]
> --DOCSHELL 0x7f3885e9a800 == 1 [pid = 28167] [id = 3]
> --DOCSHELL 0x7f3883d58000 == 0 [pid = 28167] [id = 4]
> --DOMWINDOW == 13 (0x7f3880d7f800) [pid = 28167] [serial = 14] [outer = (nil)] [url = about:blank]
> --DOMWINDOW == 12 (0x7f3883be7000) [pid = 28167] [serial = 8] [outer = (nil)] [url = about:devtools-toolbox]
> --DOMWINDOW == 11 (0x7f3885e9b000) [pid = 28167] [serial = 6] [outer = (nil)] [url = about:devtools-toolbox]
> --DOMWINDOW == 10 (0x7f3885e9d000) [pid = 28167] [serial = 7] [outer = (nil)] [url = about:blank]
> --DOMWINDOW == 9 (0x7f38920ba800) [pid = 28167] [serial = 3] [outer = (nil)] [url = chrome://devtools/content/framework/toolbox-process-window.xul?addonID=test-devtools@mozilla.org]
> --DOMWINDOW == 8 (0x7f38920bb800) [pid = 28167] [serial = 4] [outer = (nil)] [url = about:blank]
> --DOMWINDOW == 7 (0x7f3894ee6000) [pid = 28167] [serial = 1] [outer = (nil)] [url = resource://gre-resources/hiddenWindow.html]
> --DOMWINDOW == 6 (0x7f3894ee7000) [pid = 28167] [serial = 2] [outer = (nil)] [url = about:blank]
> --DOMWINDOW == 5 (0x7f38820c8000) [pid = 28167] [serial = 11] [outer = (nil)] [url = data:text/html;charset=utf8,<!DOCTYPE%20html><html%20dir='ltr'>%20%20<head>%20%20%20%20<style>%20%20%20%20%20%20html,%20body%20{%20height:%20100%;%20}%20%20%20%20%20%20body%20{%20margin:%200;%20overflow:%20hidden;%20}%20%20%20%20%20%20.CodeMirror%20{%20width:%20100%;%20height:%20100%%20!important;%20line-height:%201.25%20!important;}%20%20%20%20</style><link%20rel='stylesheet'%20href='chrome://devtools/content/sourceeditor/codemirror/lib/codemirror.css'><link%20rel='stylesheet'%20href='chrome://devtools/content/sourceeditor/codemirror/addon/dialog/dialog.css'><link%20rel='stylesheet'%20href='chrome://devtools/content/sourceeditor/codemirror/mozilla.css'>%20%20</head>%20%20<body%20class='theme-body%20devtools-monospace'></body></html>]
> --DOMWINDOW == 4 (0x7f3883d58800) [pid = 28167] [serial = 9] [outer = (nil)] [url = chrome://devtools/content/debugger/debugger.xul]
> --DOMWINDOW == 3 (0x7f3883d59800) [pid = 28167] [serial = 10] [outer = (nil)] [url = about:blank]
> --DOMWINDOW == 2 (0x7f3880d7e800) [pid = 28167] [serial = 13] [outer = (nil)] [url = chrome://devtools/content/webconsole/webconsole.xul]
> --DOMWINDOW == 1 (0x7f38820df800) [pid = 28167] [serial = 12] [outer = (nil)] [url = data:text/html;charset=utf8,<!DOCTYPE%20html><html%20dir='ltr'>%20%20<head>%20%20%20%20<style>%20%20%20%20%20%20html,%20body%20{%20height:%20100%;%20}%20%20%20%20%20%20body%20{%20margin:%200;%20overflow:%20hidden;%20}%20%20%20%20%20%20.CodeMirror%20{%20width:%20100%;%20height:%20100%%20!important;%20line-height:%201.25%20!important;}%20%20%20%20</style><link%20rel='stylesheet'%20href='chrome://devtools/content/sourceeditor/codemirror/lib/codemirror.css'><link%20rel='stylesheet'%20href='chrome://devtools/content/sourceeditor/codemirror/addon/dialog/dialog.css'><link%20rel='stylesheet'%20href='chrome://devtools/content/sourceeditor/codemirror/mozilla.css'>%20%20</head>%20%20<body%20class='theme-body%20devtools-monospace'></body></html>]
> --DOMWINDOW == 0 (0x7f38952e1000) [pid = 28167] [serial = 5] [outer = (nil)] [url = resource://gre-resources/hiddenWindow.html]

Here the logs complain "LEAKED 2 !!!", but the test isn't finished yet... Why?

> nsStringStats
>  => mAllocCount:         109345
>  => mReallocCount:         5274
>  => mFreeCount:          109343  --  LEAKED 2 !!!
>  => mShareCount:          78604
>  => mAdoptCount:           3779
>  => mAdoptFreeCount:       3779
>  => Process ID: 28167, Thread ID: 139881528411968

Here `onClose` is successfully called, and `toolbox` is set to `null` (and the test continues):

> #### toolbox.onClose() ####
> 13 INFO TEST-PASS | devtools/client/aboutdebugging/test/browser_addons_debug_bootstrapped.js | Addon toolbox closed - 
> 14 INFO TEST-PASS | devtools/client/aboutdebugging/test/browser_addons_debug_bootstrapped.js | After uninstall, the addon name disappears from the list of addons: Firefox Hello,IndexedDBTest,Mochitest,mozscreenshots,Multi-process staged rollout,Pocket,Special Powers,Web Compat,WorkerTestBootstrap - 
> 15 INFO Closing about:debugging
> 16 INFO Removing tab.
> 17 INFO Tab removed and finished closing.
> 18 INFO Leaving test bound 

The test is finishing. An "about:blank" window closes... (not sure if relevant):

> --DOMWINDOW == 25 (0x7f51cff85400) [pid = 28020] [serial = 8] [outer = (nil)] [url = about:blank]
> MEMORY STAT vsizeMaxContiguous not supported in this build configuration.
> MEMORY STAT | vsize 1049MB | residentFast 303MB | heapAllocated 87MB
> 19 INFO TEST-OK | devtools/client/aboutdebugging/test/browser_addons_debug_bootstrapped.js | took 18900ms

Test complete.

> ++DOCSHELL 0x7f3e8cd72800 == 2 [pid = 28117] [id = 2]
> ++DOMWINDOW == 3 (0x7f3e8d9ecc00) [pid = 28117] [serial = 3] [outer = (nil)]
> 20 INFO checking window state
> ++DOMWINDOW == 26 (0x7f51c5ed0000) [pid = 28020] [serial = 27] [outer = 0x7f51d10e0000]
> ++DOMWINDOW == 4 (0x7f3e8db9e000) [pid = 28117] [serial = 4] [outer = 0x7f3e8d9ecc00]
> ++DOMWINDOW == 27 (0x7f51c5196400) [pid = 28020] [serial = 28] [outer = 0x7f51d1f97800]
> --DOCSHELL 0x7f51ca645800 == 8 [pid = 28020] [id = 9]
> ++DOMWINDOW == 28 (0x7f51c5ede800) [pid = 28020] [serial = 29] [outer = 0x7f51d10e0000]
> ++DOMWINDOW == 29 (0x7f51ca6b7400) [pid = 28020] [serial = 30] [outer = 0x7f51d1f97800]
> --DOCSHELL 0x7f3e8f4b7800 == 1 [pid = 28117] [id = 1]
> --DOMWINDOW == 3 (0x7f3e8de69400) [pid = 28117] [serial = 2] [outer = (nil)] [url = about:blank]
> --DOMWINDOW == 2 (0x7f3e8df0d000) [pid = 28117] [serial = 1] [outer = (nil)] [url = about:blank]
> --DOCSHELL 0x7f51c61d4000 == 7 [pid = 28020] [id = 10]
> --DOCSHELL 0x7f51c7ef5000 == 6 [pid = 28020] [id = 7]
> --DOCSHELL 0x7f51c6f80000 == 5 [pid = 28020] [id = 8]
> --DOMWINDOW == 28 (0x7f51c7cfd400) [pid = 28020] [serial = 20] [outer = (nil)] [url = about:blank]
> --DOMWINDOW == 27 (0x7f51cba9f400) [pid = 28020] [serial = 13] [outer = (nil)] [url = about:blank]
> --DOMWINDOW == 26 (0x7f51cff8fc00) [pid = 28020] [serial = 9] [outer = (nil)] [url = about:blank]
> --DOMWINDOW == 25 (0x7f51e4bd3000) [pid = 28020] [serial = 2] [outer = (nil)] [url = about:blank]
> --DOMWINDOW == 24 (0x7f51c7c36400) [pid = 28020] [serial = 17] [outer = (nil)] [url = about:blank]
> --DOMWINDOW == 23 (0x7f51d0273000) [pid = 28020] [serial = 12] [outer = (nil)] [url = about:blank]
> --DOMWINDOW == 22 (0x7f51c5b58000) [pid = 28020] [serial = 23] [outer = (nil)] [url = about:blank]
> --DOMWINDOW == 21 (0x7f51cf9e4000) [pid = 28020] [serial = 10] [outer = (nil)] [url = about:blank]
> --DOMWINDOW == 20 (0x7f51c5ed0000) [pid = 28020] [serial = 27] [outer = (nil)] [url = about:blank]
> --DOMWINDOW == 19 (0x7f51c7cee400) [pid = 28020] [serial = 18] [outer = (nil)] [url = about:newtab]
> --DOMWINDOW == 18 (0x7f51d0271000) [pid = 28020] [serial = 11] [outer = (nil)] [url = about:blank]
> --DOMWINDOW == 17 (0x7f51c5196400) [pid = 28020] [serial = 28] [outer = (nil)] [url = about:blank]
> --DOMWINDOW == 16 (0x7f51cea23400) [pid = 28020] [serial = 26] [outer = (nil)] [url = about:blank]
> --DOMWINDOW == 15 (0x7f51c61d1800) [pid = 28020] [serial = 24] [outer = (nil)] [url = data:application/vnd.mozilla.xul+xml;charset=utf-8,<window%20id='win'/>]
> --DOMWINDOW == 14 (0x7f51c7c31000) [pid = 28020] [serial = 16] [outer = (nil)] [url = about:newtab]
> --DOMWINDOW == 13 (0x7f51c5192000) [pid = 28020] [serial = 25] [outer = (nil)] [url = about:blank]
> --DOMWINDOW == 12 (0x7f51ca646000) [pid = 28020] [serial = 22] [outer = (nil)] [url = data:application/vnd.mozilla.xul+xml;charset=utf-8,<window%20id='win'/>]
> Completed ShutdownLeaks collections in process 28117
> Completed ShutdownLeaks collections in process 28020
> 21 INFO TEST-START | Shutdown
> 22 INFO Browser Chrome Test Summary
> 23 INFO Passed:  7
> 24 INFO Failed:  0
> 25 INFO Todo:    0
> 26 INFO Mode:    e10s
> 27 INFO *** End BrowserChrome Test Results ***
> --DOCSHELL 0x7f51ca34d000 == 4 [pid = 28020] [id = 6]
> --DOCSHELL 0x7f51e4bd1800 == 3 [pid = 28020] [id = 1]
> [Child 28117] WARNING: NS_ENSURE_TRUE(maybeContext) failed: file /home/user/firefox/xpcom/threads/nsThread.cpp, line 887
> --DOCSHELL 0x7f3e8cd72800 == 0 [pid = 28117] [id = 2]
> --DOMWINDOW == 1 (0x7f3e8db9e000) [pid = 28117] [serial = 4] [outer = (nil)] [url = about:blank]
> --DOMWINDOW == 0 (0x7f3e8d9ecc00) [pid = 28117] [serial = 3] [outer = (nil)] [url = about:blank]
> nsStringStats
>  => mAllocCount:          46322
>  => mReallocCount:         1051
>  => mFreeCount:           46322
>  => mShareCount:          15238
>  => mAdoptCount:           1485
>  => mAdoptFreeCount:       1485
>  => Process ID: 28117, Thread ID: 139906974247680

Here, it looks like a bunch of windows are getting closed, including serials 19 and 21 (but they're still considered as leaks below):

> --DOCSHELL 0x7f51d10df800 == 2 [pid = 28020] [id = 3]
> --DOCSHELL 0x7f51e0a55000 == 1 [pid = 28020] [id = 2]
> --DOCSHELL 0x7f51d10e0800 == 0 [pid = 28020] [id = 4]
> [Parent 28020] WARNING: Unable to retrieve the tooltip node document.: file /home/user/firefox/layout/xul/nsXULTooltipListener.cpp, line 564
> ]: ]: [Parent 28020] WARNING: NS_ENSURE_TRUE(maybeContext) failed: file /home/user/firefox/xpcom/threads/nsThread.cpp, line 887
> [Parent 28020] WARNING: 'NS_FAILED(RemovePermissionChangeObserver())', file /home/user/firefox/dom/notification/Notification.cpp, line 692
> --DOMWINDOW == 11 (0x7f51e0a56800) [pid = 28020] [serial = 4] [outer = (nil)] [url = about:blank]
> --DOMWINDOW == 10 (0x7f51e4bd2000) [pid = 28020] [serial = 1] [outer = (nil)] [url = resource://gre-resources/hiddenWindow.html]
> --DOMWINDOW == 9 (0x7f51c7cfa800) [pid = 28020] [serial = 19] [outer = (nil)] [url = about:debugging#addons]
> --DOMWINDOW == 8 (0x7f51de736400) [pid = 28020] [serial = 21] [outer = (nil)] [url = about:debugging#addons]
> --DOMWINDOW == 7 (0x7f51ca6b7400) [pid = 28020] [serial = 30] [outer = (nil)] [url = about:blank]
> --DOMWINDOW == 6 (0x7f51d1f97800) [pid = 28020] [serial = 7] [outer = (nil)] [url = about:blank]
> --DOMWINDOW == 5 (0x7f51c5ede800) [pid = 28020] [serial = 29] [outer = (nil)] [url = about:blank]
> --DOMWINDOW == 4 (0x7f51d10e0000) [pid = 28020] [serial = 6] [outer = (nil)] [url = about:blank]
> --DOMWINDOW == 3 (0x7f51ca34e800) [pid = 28020] [serial = 15] [outer = (nil)] [url = about:blank]
> --DOMWINDOW == 2 (0x7f51ca34d800) [pid = 28020] [serial = 14] [outer = (nil)] [url = chrome://mochikit/content/browser-harness.xul]
> --DOMWINDOW == 1 (0x7f51e0a55800) [pid = 28020] [serial = 3] [outer = (nil)] [url = chrome://browser/content/browser.xul]
> --DOMWINDOW == 0 (0x7f51e087c000) [pid = 28020] [serial = 5] [outer = (nil)] [url = resource://gre-resources/hiddenWindow.html]
> nsStringStats
>  => mAllocCount:         271720
>  => mReallocCount:        10441
>  => mFreeCount:          271720
>  => mShareCount:         154865
>  => mAdoptCount:           6072
>  => mAdoptFreeCount:       6072
>  => Process ID: 28020, Thread ID: 139990247233344
> TEST-INFO | Main app process: exit 0

Here the logs complain again about 2 leaked windows (didn't they just close above?):

> TEST-UNEXPECTED-FAIL | devtools/client/aboutdebugging/test/browser_addons_debug_bootstrapped.js | leaked 2 window(s) until shutdown [url = about:debugging#addons]
> TEST-INFO | devtools/client/aboutdebugging/test/browser_addons_debug_bootstrapped.js | windows(s) leaked: [pid = 28020] [serial = 21], [pid = 28020] [serial = 19]
> runtests.py | Application ran for: 0:00:45.927750
> zombiecheck | Reading PID log: /tmp/tmpffzU6gpidlog
> ==> process 28020 launched child process 28117
> zombiecheck | Checking for orphan process with PID: 28117
> Stopping web server
> Stopping web socket server
> Stopping ssltunnel
> TEST-INFO | leakcheck | default process: leak threshold set at 0 bytes
> TEST-INFO | leakcheck | plugin process: leak threshold set at 0 bytes
> TEST-INFO | leakcheck | tab process: leak threshold set at 10000 bytes
> TEST-INFO | leakcheck | geckomediaplugin process: leak threshold set at 20000 bytes
> 
> == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, tab process 28117
> 
>      |<----------------Class--------------->|<-----Bytes------>|<----Objects---->|
>      |                                      | Per-Inst   Leaked|   Total      Rem|
>    0 |TOTAL                                 |       36        0|  106796        0|
> 
> nsTraceRefcnt::DumpStatistics: 520 entries
> 
> TEST-PASS | leakcheck | tab process: no leaks detected!
> 
> == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, default process 28020
> 
>      |<----------------Class--------------->|<-----Bytes------>|<----Objects---->|
>      |                                      | Per-Inst   Leaked|   Total      Rem|
>    0 |TOTAL                                 |       28        0| 1990016        0|
> 
> nsTraceRefcnt::DumpStatistics: 1357 entries
> 
> TEST-PASS | leakcheck | default process: no leaks detected!
> runtests.py | Running tests: end.
> TEST-INFO | checking window state
> Browser Chrome Test Summary
> 	Passed: 7
> 	Failed: 0
> 	Todo: 0
> 	Mode: e10s
> *** End BrowserChrome Test Results ***
> SUITE-END | took 47s

No further leaks until here. I'm not quire sure what to make of this test log, nor how to further investigate the leaked windows. Alex, do you have any more ideas we could try?
Flags: needinfo?(poirot.alex)
(In reply to Jan Keromnes [:janx] from comment #25)
> However, it seems that `onClose` is really called 

Yes. But as I stated before it has to be called before the test ends.

> (but maybe too late?).

Seems likely and I don't see you verify that in your comment.

> > #### jsterm.execute() ####
> > 12 INFO TEST-PASS | devtools/client/aboutdebugging/test/browser_addons_debug_bootstrapped.js | Received the notification message from the bootstrap.js function - 
> > #### toolbox.destroy() ####
> > --DOCSHELL 0x7f389203a000 == 5 [pid = 28167] [id = 2]
> 
> (Is this relevant?):

Here we destroy some document, the one with docshell id 5, which is not leaked as we destroy it before the test ends.


> Here it looks like a lot of windows are getting closed:

All but the one being reported as leaking.

> 
> > --DOCSHELL 0x7f38820c7800 == 4 [pid = 28167] [id = 5]
> > --DOCSHELL 0x7f3894ee5800 == 3 [pid = 28167] [id = 1]
> > --DOCSHELL 0x7f3880d7e000 == 2 [pid = 28167] [id = 6]
> > --DOCSHELL 0x7f3885e9a800 == 1 [pid = 28167] [id = 3]
> > --DOCSHELL 0x7f3883d58000 == 0 [pid = 28167] [id = 4]
> > --DOMWINDOW == 13 (0x7f3880d7f800) [pid = 28167] [serial = 14] [outer = (nil)] [url = about:blank]
> > --DOMWINDOW == 12 (0x7f3883be7000) [pid = 28167] [serial = 8] [outer = (nil)] [url = about:devtools-toolbox]
> > --DOMWINDOW == 11 (0x7f3885e9b000) [pid = 28167] [serial = 6] [outer = (nil)] [url = about:devtools-toolbox]
> > --DOMWINDOW == 10 (0x7f3885e9d000) [pid = 28167] [serial = 7] [outer = (nil)] [url = about:blank]
> > --DOMWINDOW == 9 (0x7f38920ba800) [pid = 28167] [serial = 3] [outer = (nil)] [url = chrome://devtools/content/framework/toolbox-process-window.xul?addonID=test-devtools@mozilla.org]
> > --DOMWINDOW == 8 (0x7f38920bb800) [pid = 28167] [serial = 4] [outer = (nil)] [url = about:blank]
> > --DOMWINDOW == 7 (0x7f3894ee6000) [pid = 28167] [serial = 1] [outer = (nil)] [url = resource://gre-resources/hiddenWindow.html]
> > --DOMWINDOW == 6 (0x7f3894ee7000) [pid = 28167] [serial = 2] [outer = (nil)] [url = about:blank]
> > --DOMWINDOW == 5 (0x7f38820c8000) [pid = 28167] [serial = 11] [outer = (nil)] [url = data:text/html;charset=utf8,<!DOCTYPE%20html><html%20dir='ltr'>%20%20<head>%20%20%20%20<style>%20%20%20%20%20%20html,%20body%20{%20height:%20100%;%20}%20%20%20%20%20%20body%20{%20margin:%200;%20overflow:%20hidden;%20}%20%20%20%20%20%20.CodeMirror%20{%20width:%20100%;%20height:%20100%%20!important;%20line-height:%201.25%20!important;}%20%20%20%20</style><link%20rel='stylesheet'%20href='chrome://devtools/content/sourceeditor/codemirror/lib/codemirror.css'><link%20rel='stylesheet'%20href='chrome://devtools/content/sourceeditor/codemirror/addon/dialog/dialog.css'><link%20rel='stylesheet'%20href='chrome://devtools/content/sourceeditor/codemirror/mozilla.css'>%20%20</head>%20%20<body%20class='theme-body%20devtools-monospace'></body></html>]
> > --DOMWINDOW == 4 (0x7f3883d58800) [pid = 28167] [serial = 9] [outer = (nil)] [url = chrome://devtools/content/debugger/debugger.xul]
> > --DOMWINDOW == 3 (0x7f3883d59800) [pid = 28167] [serial = 10] [outer = (nil)] [url = about:blank]
> > --DOMWINDOW == 2 (0x7f3880d7e800) [pid = 28167] [serial = 13] [outer = (nil)] [url = chrome://devtools/content/webconsole/webconsole.xul]
> > --DOMWINDOW == 1 (0x7f38820df800) [pid = 28167] [serial = 12] [outer = (nil)] [url = data:text/html;charset=utf8,<!DOCTYPE%20html><html%20dir='ltr'>%20%20<head>%20%20%20%20<style>%20%20%20%20%20%20html,%20body%20{%20height:%20100%;%20}%20%20%20%20%20%20body%20{%20margin:%200;%20overflow:%20hidden;%20}%20%20%20%20%20%20.CodeMirror%20{%20width:%20100%;%20height:%20100%%20!important;%20line-height:%201.25%20!important;}%20%20%20%20</style><link%20rel='stylesheet'%20href='chrome://devtools/content/sourceeditor/codemirror/lib/codemirror.css'><link%20rel='stylesheet'%20href='chrome://devtools/content/sourceeditor/codemirror/addon/dialog/dialog.css'><link%20rel='stylesheet'%20href='chrome://devtools/content/sourceeditor/codemirror/mozilla.css'>%20%20</head>%20%20<body%20class='theme-body%20devtools-monospace'></body></html>]
> > --DOMWINDOW == 0 (0x7f38952e1000) [pid = 28167] [serial = 5] [outer = (nil)] [url = resource://gre-resources/hiddenWindow.html]
> 
> Here the logs complain "LEAKED 2 !!!", but the test isn't finished yet...
> Why?

I don't know what means this LEAKED 2.

> > --DOMWINDOW == 25 (0x7f51cff85400) [pid = 28020] [serial = 8] [outer = (nil)] [url = about:blank]
> > MEMORY STAT vsizeMaxContiguous not supported in this build configuration.
> > MEMORY STAT | vsize 1049MB | residentFast 303MB | heapAllocated 87MB
> > 19 INFO TEST-OK | devtools/client/aboutdebugging/test/browser_addons_debug_bootstrapped.js | took 18900ms
> 
> Test complete.
> 
> > ++DOCSHELL 0x7f3e8cd72800 == 2 [pid = 28117] [id = 2]
> > ++DOMWINDOW == 3 (0x7f3e8d9ecc00) [pid = 28117] [serial = 3] [outer = (nil)]
> > 20 INFO checking window state
> > ++DOMWINDOW == 26 (0x7f51c5ed0000) [pid = 28020] [serial = 27] [outer = 0x7f51d10e0000]
> > ++DOMWINDOW == 4 (0x7f3e8db9e000) [pid = 28117] [serial = 4] [outer = 0x7f3e8d9ecc00]
> > ++DOMWINDOW == 27 (0x7f51c5196400) [pid = 28020] [serial = 28] [outer = 0x7f51d1f97800]
> > --DOCSHELL 0x7f51ca645800 == 8 [pid = 28020] [id = 9]
> > ++DOMWINDOW == 28 (0x7f51c5ede800) [pid = 28020] [serial = 29] [outer = 0x7f51d10e0000]
> > ++DOMWINDOW == 29 (0x7f51ca6b7400) [pid = 28020] [serial = 30] [outer = 0x7f51d1f97800]
> > --DOCSHELL 0x7f3e8f4b7800 == 1 [pid = 28117] [id = 1]
> > --DOMWINDOW == 3 (0x7f3e8de69400) [pid = 28117] [serial = 2] [outer = (nil)] [url = about:blank]
> > --DOMWINDOW == 2 (0x7f3e8df0d000) [pid = 28117] [serial = 1] [outer = (nil)] [url = about:blank]
> > --DOCSHELL 0x7f51c61d4000 == 7 [pid = 28020] [id = 10]
> > --DOCSHELL 0x7f51c7ef5000 == 6 [pid = 28020] [id = 7]
> > --DOCSHELL 0x7f51c6f80000 == 5 [pid = 28020] [id = 8]
> > --DOMWINDOW == 28 (0x7f51c7cfd400) [pid = 28020] [serial = 20] [outer = (nil)] [url = about:blank]
> > --DOMWINDOW == 27 (0x7f51cba9f400) [pid = 28020] [serial = 13] [outer = (nil)] [url = about:blank]
> > --DOMWINDOW == 26 (0x7f51cff8fc00) [pid = 28020] [serial = 9] [outer = (nil)] [url = about:blank]
> > --DOMWINDOW == 25 (0x7f51e4bd3000) [pid = 28020] [serial = 2] [outer = (nil)] [url = about:blank]
> > --DOMWINDOW == 24 (0x7f51c7c36400) [pid = 28020] [serial = 17] [outer = (nil)] [url = about:blank]
> > --DOMWINDOW == 23 (0x7f51d0273000) [pid = 28020] [serial = 12] [outer = (nil)] [url = about:blank]
> > --DOMWINDOW == 22 (0x7f51c5b58000) [pid = 28020] [serial = 23] [outer = (nil)] [url = about:blank]
> > --DOMWINDOW == 21 (0x7f51cf9e4000) [pid = 28020] [serial = 10] [outer = (nil)] [url = about:blank]
> > --DOMWINDOW == 20 (0x7f51c5ed0000) [pid = 28020] [serial = 27] [outer = (nil)] [url = about:blank]
> > --DOMWINDOW == 19 (0x7f51c7cee400) [pid = 28020] [serial = 18] [outer = (nil)] [url = about:newtab]
> > --DOMWINDOW == 18 (0x7f51d0271000) [pid = 28020] [serial = 11] [outer = (nil)] [url = about:blank]
> > --DOMWINDOW == 17 (0x7f51c5196400) [pid = 28020] [serial = 28] [outer = (nil)] [url = about:blank]
> > --DOMWINDOW == 16 (0x7f51cea23400) [pid = 28020] [serial = 26] [outer = (nil)] [url = about:blank]
> > --DOMWINDOW == 15 (0x7f51c61d1800) [pid = 28020] [serial = 24] [outer = (nil)] [url = data:application/vnd.mozilla.xul+xml;charset=utf-8,<window%20id='win'/>]
> > --DOMWINDOW == 14 (0x7f51c7c31000) [pid = 28020] [serial = 16] [outer = (nil)] [url = about:newtab]
> > --DOMWINDOW == 13 (0x7f51c5192000) [pid = 28020] [serial = 25] [outer = (nil)] [url = about:blank]
> > --DOMWINDOW == 12 (0x7f51ca646000) [pid = 28020] [serial = 22] [outer = (nil)] [url = data:application/vnd.mozilla.xul+xml;charset=utf-8,<window%20id='win'/>]
> > Completed ShutdownLeaks collections in process 28117
> > Completed ShutdownLeaks collections in process 28020
> > 21 INFO TEST-START | Shutdown
> > 22 INFO Browser Chrome Test Summary
> > 23 INFO Passed:  7
> > 24 INFO Failed:  0
> > 25 INFO Todo:    0
> > 26 INFO Mode:    e10s
> > 27 INFO *** End BrowserChrome Test Results ***
> > --DOCSHELL 0x7f51ca34d000 == 4 [pid = 28020] [id = 6]
> > --DOCSHELL 0x7f51e4bd1800 == 3 [pid = 28020] [id = 1]
> > [Child 28117] WARNING: NS_ENSURE_TRUE(maybeContext) failed: file /home/user/firefox/xpcom/threads/nsThread.cpp, line 887
> > --DOCSHELL 0x7f3e8cd72800 == 0 [pid = 28117] [id = 2]
> > --DOMWINDOW == 1 (0x7f3e8db9e000) [pid = 28117] [serial = 4] [outer = (nil)] [url = about:blank]
> > --DOMWINDOW == 0 (0x7f3e8d9ecc00) [pid = 28117] [serial = 3] [outer = (nil)] [url = about:blank]
> > nsStringStats
> >  => mAllocCount:          46322
> >  => mReallocCount:         1051
> >  => mFreeCount:           46322
> >  => mShareCount:          15238
> >  => mAdoptCount:           1485
> >  => mAdoptFreeCount:       1485
> >  => Process ID: 28117, Thread ID: 139906974247680
> 
> Here, it looks like a bunch of windows are getting closed, including serials
> 19 and 21 (but they're still considered as leaks below):

This is when the test harness is done running tests. It forces closing the browser windows, that's why you see so many documents being destroyed. By any test leftover is getting closed here.

> 
> > --DOCSHELL 0x7f51d10df800 == 2 [pid = 28020] [id = 3]
> > --DOCSHELL 0x7f51e0a55000 == 1 [pid = 28020] [id = 2]
> > --DOCSHELL 0x7f51d10e0800 == 0 [pid = 28020] [id = 4]
> > [Parent 28020] WARNING: Unable to retrieve the tooltip node document.: file /home/user/firefox/layout/xul/nsXULTooltipListener.cpp, line 564
> > ]: ]: [Parent 28020] WARNING: NS_ENSURE_TRUE(maybeContext) failed: file /home/user/firefox/xpcom/threads/nsThread.cpp, line 887
> > [Parent 28020] WARNING: 'NS_FAILED(RemovePermissionChangeObserver())', file /home/user/firefox/dom/notification/Notification.cpp, line 692
> > --DOMWINDOW == 11 (0x7f51e0a56800) [pid = 28020] [serial = 4] [outer = (nil)] [url = about:blank]
> > --DOMWINDOW == 10 (0x7f51e4bd2000) [pid = 28020] [serial = 1] [outer = (nil)] [url = resource://gre-resources/hiddenWindow.html]
> > --DOMWINDOW == 9 (0x7f51c7cfa800) [pid = 28020] [serial = 19] [outer = (nil)] [url = about:debugging#addons]
> > --DOMWINDOW == 8 (0x7f51de736400) [pid = 28020] [serial = 21] [outer = (nil)] [url = about:debugging#addons]
> > --DOMWINDOW == 7 (0x7f51ca6b7400) [pid = 28020] [serial = 30] [outer = (nil)] [url = about:blank]
> > --DOMWINDOW == 6 (0x7f51d1f97800) [pid = 28020] [serial = 7] [outer = (nil)] [url = about:blank]
> > --DOMWINDOW == 5 (0x7f51c5ede800) [pid = 28020] [serial = 29] [outer = (nil)] [url = about:blank]
> > --DOMWINDOW == 4 (0x7f51d10e0000) [pid = 28020] [serial = 6] [outer = (nil)] [url = about:blank]
> > --DOMWINDOW == 3 (0x7f51ca34e800) [pid = 28020] [serial = 15] [outer = (nil)] [url = about:blank]
> > --DOMWINDOW == 2 (0x7f51ca34d800) [pid = 28020] [serial = 14] [outer = (nil)] [url = chrome://mochikit/content/browser-harness.xul]
> > --DOMWINDOW == 1 (0x7f51e0a55800) [pid = 28020] [serial = 3] [outer = (nil)] [url = chrome://browser/content/browser.xul]
> > --DOMWINDOW == 0 (0x7f51e087c000) [pid = 28020] [serial = 5] [outer = (nil)] [url = resource://gre-resources/hiddenWindow.html]
> > nsStringStats
> >  => mAllocCount:         271720
> >  => mReallocCount:        10441
> >  => mFreeCount:          271720
> >  => mShareCount:         154865
> >  => mAdoptCount:           6072
> >  => mAdoptFreeCount:       6072
> >  => Process ID: 28020, Thread ID: 139990247233344
> > TEST-INFO | Main app process: exit 0
> 
> Here the logs complain again about 2 leaked windows (didn't they just close
> above?):

Yes, but too late.

> No further leaks until here. I'm not quire sure what to make of this test
> log, nor how to further investigate the leaked windows. Alex, do you have
> any more ideas we could try?

I'm pretty confident it has to do with the `toolbox` global. That may just be a timing leak, but you didn't verified that onClose was called before test end. You should try to ensure it is.
Test end means before the generator passed to add_task ends.
To verify that you can add a dump call after `yield closeAboutDebugging();`. This dump() call has to be done before the dump added to onClose which nullify the toolbox variable.
Flags: needinfo?(poirot.alex)
If that's called before test end, it may be worth ensuring that devtools/client/framework/ToolboxProcess.jsm: BrowserToolboxProcess.close is also called before test end. We might also be leaking stuff via BrowserToolboxProcess._options which keeps references to some objects crafted by about:debugging (addonId string)
It looks like I also leak two windows in bug 1188981: https://treeherder.mozilla.org/#/jobs?repo=try&revision=88d6adfa187d&selectedJob=22255179

Will report back here when I fixed it.
Hi Jan,

Do you have any idea how we can solve this issue? 

I have no clue to fix leaked issue currently :(

Thanks!
Flags: needinfo?(janx)
Hi Joseph,

These leaks are hard to figure out, because there is no clear pointer to the code that's causing the problem (at least that I know of). I'm still trying to figure out the leaks with my patch in bug 1188981, but I don't really know how to do that either.

I'll let you know if I manage to fix my leaks, and try to help you with yours. So far my approach has been to reproduce it locally with a debug build, and then try commenting out lines from the broken test to see if that fixes the leak. Generally, I suspect that opening a toolbox is what causes the leaks, but I don't know how to fix it.
Flags: needinfo?(janx)
Ok I fixed my leaks with help of :nbp.

It turns out that all variables created in the test (notably `document`) were captured by the closures in the mocked push service, even though the variables were declared *after* the closures. That's because JS engine bug 894971 caused all `let` variables to be hoisted to the top of the generator, so before the closures, leading to the capture.

The solution was to simply destroy the mocked push service, along with its closures and associates scope chains.
Rebased, r+ carried over.
Attachment #8765041 - Flags: review+
Attachment #8755751 - Attachment is obsolete: true
While dissecting the code, I found that the newly added `onClose` listener was being leaked by BrowserToolboxProcess.init() (even when we don't keep its instance alive).

Using `.once()` instead of `.on()` for `onClose` listeners fixed the leaks locally for me. Try should be happier with this, but I'm not sure I'm fixing this leak the right way.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=065ea7ab67a9
Attachment #8765044 - Flags: review?(poirot.alex)
Comment on attachment 8765044 [details] [diff] [review]
Fix a few BrowserToolboxProcess leaks.

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

This patch doesn't fix the BrowserToolboxProcess leak.
It breaks the leak between BrowserToolboxProcess and the arguments passed to BrowsertoolboxProcess.init (the onClose callback, which keeps about:debugging document alive and is reported as leaking).
Unfortunately, we only have docshell/document leak reporter. We do not report JSM or any arbitrary JS class leak (it is very hard to determine)

It looks like there is even more stuff being leaked.
this.loader and this.debuggerServer are not freed.
this.debuggerServer holds the BrowserToolboxProcess alive due to the connectionchange listener.

Here is a trick to see if something is freed or not:
  let ref = Cu.getWeakReference(suspiciousObjectThatMayBeLeaked);
  require("sdk/timers").setInterval(function () {
    Cu.forceGC(); Cu.forceCC();
    if (ref.get()) {
      dump("leaking: "+ref.get()+"\n");
    } else {
      dump("freed!\n");
    }
  }, 50);

But this patch makes sense and at least prevent leaking BrowserToolboxProcess callsites, which is great.
Attachment #8765044 - Flags: review?(poirot.alex) → review+
Two additional leak fixes.
This one, to prevent leaking the BrowserToolboxProcess instances from the connectionchange listeners.
Unfortunately, debuggerServer leaks. I haven't been able to figure out why in a reasonable period of time.
debuggerServer is complex. This is a module. And a complex one.

As Jan's patch it as least kill yet another level of leak.
With this patch, BrowserToolboxProcess should be freed. It should also fix joseph leak.
Attachment #8765483 - Flags: review?(jryans)
While chasing debuggerServer leak I saw that BrowserToolboxProcess was forcing its "loader" instance to leak.
Here is something to stop doing so.
Unfortunately, it is not enough to free debuggerServer variable.
Attachment #8765486 - Flags: review?(jryans)
Fixed eslint.
Attachment #8765514 - Flags: review?(jryans)
Attachment #8765486 - Attachment is obsolete: true
Attachment #8765486 - Flags: review?(jryans)
Comment on attachment 8765514 [details] [diff] [review]
Free loader created by BrowserToolboxProcess.

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

::: devtools/client/framework/ToolboxProcess.jsm
@@ +249,5 @@
>  
>      this._telemetry.toolClosed("jsbrowserdebugger");
>      if (this.debuggerServer) {
>        this.debuggerServer.off("connectionchange", this.emit);
> +      this.debuggerServer.destroy("destroy");

Did you mean to pass this to loader.destroy as the reason?  This destroy doesn't have an params...

::: devtools/shared/Loader.jsm
@@ +81,5 @@
>    Services.obs.addObserver(this, "devtools-unload", false);
>  };
>  
>  DevToolsLoader.prototype = {
> +  destroy: function (reason) {

Is reason required?  If so, can we give it a default value?  Every other `destroy` API we have doesn't take an arg, so this is a bit surprising.
Attachment #8765514 - Flags: review?(jryans) → feedback+
(In reply to J. Ryan Stinnett [:jryans] (use ni?) from comment #39)
> Comment on attachment 8765514 [details] [diff] [review]
> Free loader created by BrowserToolboxProcess.
> 
> Review of attachment 8765514 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: devtools/client/framework/ToolboxProcess.jsm
> @@ +249,5 @@
> >  
> >      this._telemetry.toolClosed("jsbrowserdebugger");
> >      if (this.debuggerServer) {
> >        this.debuggerServer.off("connectionchange", this.emit);
> > +      this.debuggerServer.destroy("destroy");
> 
> Did you mean to pass this to loader.destroy as the reason?  This destroy
> doesn't have an params...

Oops, yes...

> ::: devtools/shared/Loader.jsm
> @@ +81,5 @@
> >    Services.obs.addObserver(this, "devtools-unload", false);
> >  };
> >  
> >  DevToolsLoader.prototype = {
> > +  destroy: function (reason) {
> 
> Is reason required?  If so, can we give it a default value?  Every other
> `destroy` API we have doesn't take an arg, so this is a bit surprising.

reason isn't used much anywhere, it is a SDK convention.
But I did that (make it optional by having default value set to "shutdown").
And I'm using default reason when destroying from the Browser Toolbox.
The only two existing reasons I know about are: shutdown and uninstall.
Attachment #8765792 - Flags: review?(jryans)
Attachment #8765514 - Attachment is obsolete: true
Previous try push is for all patches at once.
I'll checkin all of them once try is green and last patch is r+.
Thanks a lot Joseph, Alex and Ryan for fixing this bug! I'm glad these leaks didn't block us for too long.
Thanks so much for fixing this! This bug has, well, bugged me for ages, until I finally got around to filing it :).
Thanks for everyone's help :)
I have reproduced this bug in firefox nightly 49.0a1(2016-04-27) as comment 0 with windows 10 (64 bit).
But in latest firefox 50.0a2 when i open about:debugging and click on the "Debug" button next to an add-on several times there is a new message showing in a window it's
"Firefox Developer Edition closed unexpectedly while starting.This might be caused by add-ons or other problems.You can try to resolve the problem by troubleshooting in Safe Mode.
Start in safe mode"
i also find same result on latest firefox nightly 51.0a1.

Firefox Aurora 50.0a2
Build ID 20160803004014
User Agent 	Mozilla/5.0 (Windows NT 10.0; WOW64; rv:50.0) Gecko/20100101 Firefox/50.0

Firefox Nightly 51.0a1
Build ID  20160803030226
User Agent 	Mozilla/5.0 (Windows NT 10.0; WOW64; rv:51.0) Gecko/20100101 Firefox/51.0

Attached File: https://drive.google.com/file/d/0B3l-rfIMikeyWmJNYm02Q1JmWmc/view?usp=sharing

[bugday-20160803]
Status: RESOLVED → VERIFIED
status-firefox50: fixed → verified
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: