620832 - Web console attempts to remove its observers multiple times

Status: VERIFIED FIXED

(DevTools :: General, defect)

Description

[Josh Matthews [:jdm]]

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

Comment 1

[Josh Matthews [:jdm]]

Attachment: Ensure web console observers are only removed once.

Comment 2

[Kevin Dangoor]

This may be covered by a revised patch in bug 612658 (cc'ing ddahl to see what he thinks).

Comment 3

[David Dahl :ddahl]

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

[David Dahl :ddahl]

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

Comment 5

[:Gavin Sharp [email: [e-mail]]]

I'd like to understand why there are unbalanced calls to suspend()/wakeup(), rather than wallpapering over that issue...

Comment 6

[Josh Matthews [:jdm]]

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

Comment 7

[Rob Campbell [:rc] (:robcee)]

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.

Comment 8

[Mihai Sucan [:msucan]]

Attachment: [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!

Comment 9

[Rob Campbell [:rc] (:robcee)]

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.

Comment 10

[Mihai Sucan [:msucan]]

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

Thanks for the feedback+ Rob!

Asking for review from Gavin.

Comment 11

[:Gavin Sharp [email: [e-mail]]]

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

Comment 12

[Mihai Sucan [:msucan]]

(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?

Comment 13

[Rob Campbell [:rc] (:robcee)]

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

Comment 14

[Rob Campbell [:rc] (:robcee)]

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.

Comment 15

[Shawn Wilsher :sdwilsh]

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.

Comment 16

[Mihai Sucan [:msucan]]

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

Comment 17

[Rob Campbell [:rc] (:robcee)]

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

http://hg.mozilla.org/projects/devtools/rev/8be464aa5841

Comment 18

[Rob Campbell [:rc] (:robcee)]

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.

Comment 19

[Mihai Sucan [:msucan]]

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

Pushed:
http://hg.mozilla.org/projects/devtools/rev/23e0f778f2f9

Comment 20

[Rob Campbell [:rc] (:robcee)]

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

http://hg.mozilla.org/mozilla-central/rev/8be464aa5841

Comment 21

[AndreiD[QA]]

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.