Web console attempts to remove its observers multiple times

VERIFIED FIXED in Firefox 6

Status

()

Firefox
Developer Tools
VERIFIED FIXED
6 years ago
6 years ago

People

(Reporter: jdm, Assigned: msucan)

Tracking

unspecified
Firefox 6
Points:
---

Firefox Tracking Flags

(Not tracked)

Details

(Whiteboard: [patchclean:0210][console-1][fixed-in-devtools][merged-to-mozilla-central])

Attachments

(1 attachment, 1 obsolete attachment)

(Reporter)

Description

6 years ago
It's harmless, but it's noisy and distracting in the console, as there are a number of assertion failures and javascript exceptions.
(Reporter)

Comment 1

6 years ago
Created attachment 499195 [details] [diff] [review]
Ensure web console observers are only removed once.

Comment 2

6 years ago
This may be covered by a revised patch in bug 612658 (cc'ing ddahl to see what he thinks).
Blocks: 593956

Comment 3

6 years ago
From what I can tell it is just the manual calling of removeObserver("content-document-global-created") in  HWO_uninit()

However, When I remove that line in the patch in bug 612658 we leak an entire DOMWindow - at least that is what I am dealing with right now. I will add this patch to my queue to see how it affects the tests.

Comment 4

6 years ago
(In reply to comment #3)

> However, When I remove that line in the patch in bug 612658 we leak an entire
> DOMWindow - at least that is what I am dealing with right now. I will add this
> patch to my queue to see how it affects the tests.

Apparently, these issues are unrelated.

Updated

6 years ago
Attachment #499195 - Flags: feedback+

Updated

6 years ago
Attachment #499195 - Flags: review?(gavin.sharp)
I'd like to understand why there are unbalanced calls to suspend()/wakeup(), rather than wallpapering over that issue...
Attachment #499195 - Flags: review?(gavin.sharp) → review-
(Reporter)

Comment 6

6 years ago
First we hit the quit-application-granted observer, so CAO_shutdown is called.  Then a window unload triggers HS_suspend, so CAO_shutdown is called again.  Next there's xpcom-shutdown, so HWO_uninit tries to run again.  An interesting point here is that since the xpcom-shutdown isn't removed when HWO_uninit is called from HS_suspend, we actually leak an observer for every time the web console is opened and closed (ie. toggle it 5 times, you'll see five assertions).
I think Josh hit it. We're listening for a bunch of things and not clearing the observer quickly enough when we get the quit-application-granted listener.
(Assignee)

Comment 8

6 years ago
Created attachment 511421 [details] [diff] [review]
[checked-in][in-devtools] proposed fix

Proposed fix.

Gavin's right. We shouldn't wallpaper over the issue of unbalanced calls to suspend/wakeup the HUDService.

I added some logging code and the current situation is as follows:

1. Start Firefox.
2. Open Web Console. Result:

HUDService.wakeup()
  HUDService.startHTTPObservation()
  HUDWindowObserver.init()
  HUDConsoleObserver.init()
  ConsoleAPIObserver.init()
HUDService.wakeup() end

That looks fine.

3. Close the Web Console. Result:

HUDService.suspend()
  HUDWindowObserver.uninit()
    HUDService.shutdown()
  HUDWindowObserver.uninit() end
  HUDConsoleObserver.uninit()
  ConsoleAPIObserver.shutdown()
HUDService suspend() end

Again, this looks fine.

4. Open the Web Console again. Same result as in step 2.

5. Press Ctrl-Q (to quit Firefox). Result:

ConsoleAPIObserver.observe() quit-application-granted
  ConsoleAPIObserver.shutdown()
ConsoleAPIObserver.observe() quit-application-granted end
HUDService suspend() - this is called by the window close event handler
  HUDWindowObserver.uninit()
    HUDService shutdown()
  HUDWindowObserver.uninit() end
  HUDConsoleObserver.uninit()
  ConsoleAPIObserver.shutdown()
HUDWindowObserver observe() xpcom-shutdown
  HUDWindowObserver.uninit()
HUDWindowObserver.observe() xpcom-shutdown
  HUDWindowObserver.uninit()

This shows that the observer for xpcom-shutdown was never removed, and that ConsoleAPIObserver.shutdown() is called twice. And that, generally, the execution is not "clean".


With this patch applied steps 2 and 3 remain identical, but the result of step 5 changes to:

ConsoleAPIObserver.observe() quit-application-granted
  HUDService.shutdown()
    HUDService suspend()
      HUDWindowObserver.uninit()
      HUDConsoleObserver.uninit()
      ConsoleAPIObserver.shutdown()
    HUDService.suspend() end
  HUDService.shutdown() end
ConsoleAPIObserver.observe() quit-application-granted end

Which is quite cleaner and saner.

Feedback is welcome. Thanks!
Assignee: nobody → mihai.sucan
Attachment #499195 - Attachment is obsolete: true
Status: NEW → ASSIGNED
Attachment #511421 - Flags: feedback?(rcampbell)
(Assignee)

Updated

6 years ago
OS: Mac OS X → All
Hardware: x86 → All
Whiteboard: [patchclean:0210]
Comment on attachment 511421 [details] [diff] [review]
[checked-in][in-devtools] proposed fix

nice analysis! I wondered if we were answering the same listener more than once in here.
Attachment #511421 - Flags: feedback?(rcampbell) → feedback+
(Assignee)

Comment 10

6 years ago
Comment on attachment 511421 [details] [diff] [review]
[checked-in][in-devtools] proposed fix

Thanks for the feedback+ Rob!

Asking for review from Gavin.
Attachment #511421 - Flags: review?(gavin.sharp)
It seems wrong that the ConsoleAPIObserver (a completely separate object) is responsible for shutting down the HUDService (i.e. calling HUDService.shutdown()). It also seems wrong for the HUDWindowObserver to be doing it. Shouldn't the HUDService have its own observer that shuts itself down? Removing as many inter-dependencies as possible seems like it would simplify things...
(Assignee)

Comment 12

6 years ago
(In reply to comment #11)
> It seems wrong that the ConsoleAPIObserver (a completely separate object) is
> responsible for shutting down the HUDService (i.e. calling
> HUDService.shutdown()). It also seems wrong for the HUDWindowObserver to be
> doing it. Shouldn't the HUDService have its own observer that shuts itself
> down? Removing as many inter-dependencies as possible seems like it would
> simplify things...

You are correct, but ultimately it's just a legacy naming issue (and a code organization problem).

The ConsoleAPIObserver uses Services.obs.addObserver(this, "quit-application-granted"), which is fired first, and this is why I use it to call HUDService.shutdown(). This topic it listens for is completely unrelated to the other topic (console-api-log-event).

Additionally, HUDWindowObserver uses Services.obs.addObserver(this, "xpcom-shutdown") which is fired later and which I do not use to call HUDService.shutdown() in the updated patch. Again, this topic it listens for is completely unrelated to the other topic (content-document-global-created).

HUDWindowObserver, HUDConsoleObserver and ConsoleAPIObserver are all HUDService listeners in the broad sense. They don't serve other purposes. Still, they could be consolidated into something more compact.

I agree we can do further cleanup and reorganize the code to be less confusing. I chose to do a minimal patch, in the hope we could push it earlier (easier to review, less prone to regressions, etc). Thoughts?
(In reply to comment #11)
> It seems wrong that the ConsoleAPIObserver (a completely separate object) is
> responsible for shutting down the HUDService (i.e. calling
> HUDService.shutdown()). It also seems wrong for the HUDWindowObserver to be
> doing it. Shouldn't the HUDService have its own observer that shuts itself
> down? Removing as many inter-dependencies as possible seems like it would
> simplify things...

I'm ambivalent about it at this point. We might as well patch the code we have already rather than reorganize.

We can file a separate bug to nix the extraneous observers for post fx4.

Updated

6 years ago
Whiteboard: [patchclean:0210] → [patchclean:0210][console-1]
Comment on attachment 511421 [details] [diff] [review]
[checked-in][in-devtools] proposed fix

shawn, could you give us an r+ on this? We've already reviewed internally and it's a simple fix.
Attachment #511421 - Flags: review?(sdwilsh)
Attachment #511421 - Flags: review?(gavin.sharp)
Attachment #511421 - Flags: review+
Comment on attachment 511421 [details] [diff] [review]
[checked-in][in-devtools] proposed fix

r=sdwilsh assuming a follow-up bug is filed to address comment 11 and comment 12 and that gets fixed soonish.  This is better than before, although still not perfect.  I'd rather not let perfect be the enemy of good though.
Attachment #511421 - Flags: review?(sdwilsh) → review+
(Assignee)

Comment 16

6 years ago
Thanks for the r+ Shawn!

Rob: I retested the patch on my system, devtools repo. It still applies cleanly, and all tests pass (opt and dbg builds).
(Assignee)

Updated

6 years ago
Whiteboard: [patchclean:0210][console-1] → [patchclean:0210][console-1][checkin]
Comment on attachment 511421 [details] [diff] [review]
[checked-in][in-devtools] proposed fix

http://hg.mozilla.org/projects/devtools/rev/8be464aa5841
Attachment #511421 - Attachment description: proposed fix → [in-devtools] proposed fix
Whiteboard: [patchclean:0210][console-1][checkin] → [patchclean:0210][console-1][in-devtools][merge-m-c]
Whiteboard: [patchclean:0210][console-1][in-devtools][merge-m-c] → [patchclean:0210][console-1][fixed-in-devtools][merge-m-c]
Whiteboard: [patchclean:0210][console-1][fixed-in-devtools][merge-m-c] → [patchclean:0210][console-1][orange]
Whiteboard: [patchclean:0210][console-1][orange] → [patchclean:0210][console-1][checkin]
Comment on attachment 511421 [details] [diff] [review]
[checked-in][in-devtools] proposed fix

this should be safe to reland when we get a green run.
Attachment #511421 - Attachment description: [in-devtools] proposed fix → proposed fix
(Assignee)

Comment 19

6 years ago
Comment on attachment 511421 [details] [diff] [review]
[checked-in][in-devtools] proposed fix

Pushed:
http://hg.mozilla.org/projects/devtools/rev/23e0f778f2f9
Attachment #511421 - Attachment description: proposed fix → [in-devtools] proposed fix
(Assignee)

Updated

6 years ago
Whiteboard: [patchclean:0210][console-1][checkin] → [patchclean:0210][console-1][fixed-in-devtools]
Status: ASSIGNED → RESOLVED
Last Resolved: 6 years ago
Resolution: --- → FIXED
Whiteboard: [patchclean:0210][console-1][fixed-in-devtools] → [patchclean:0210][console-1][fixed-in-devtools][merged-to-mozilla-central]
Target Milestone: --- → Firefox 6
Comment on attachment 511421 [details] [diff] [review]
[checked-in][in-devtools] proposed fix

http://hg.mozilla.org/mozilla-central/rev/8be464aa5841
Attachment #511421 - Attachment description: [in-devtools] proposed fix → [checked-in][in-devtools] proposed fix

Comment 21

6 years ago
The changes made with the patch landed in central (comment 20) are visible in FX6 Beta:
i.e:
 HUDService.shutdown(); REPLACED WITH Services.obs.removeObserver(this, "xpcom-shutdown"); 
-> http://hg.mozilla.org/releases/mozilla-beta/file/084847ea02b4/toolkit/components/console/hudservice/HUDService.jsm

Setting this as Verified.
Status: RESOLVED → VERIFIED
You need to log in before you can comment on or make changes to this bug.