920436 - Permanent Jetpack orange on UX: TEST-UNEXPECTED-FAIL | tests/test-ui-button.test button added with resource URI | TypeError: aId is undefined

Status: RESOLVED FIXED

(Firefox :: Toolbars and Customization, defect)

Description

[:Gijs (he/him)]

https://tbpl.mozilla.org/php/getParsedLog.php?id=28336377&tree=UX

This went orange on all platforms, all types of builds, on this m-c merge cset:

https://tbpl.mozilla.org/?tree=UX&rev=d6406f5ecc5d

I don't see a jetpack uplift in this merge, which is worrying. How could this suddenly start failing?

Comment 1

[:Gijs (he/him)]

I can't reproduce this when running only the ui-button tests, but I can if I run the private browsing tests beforehand. So it's down to the interaction (somehow or other) of test-private-browsing.js and test-ui-button.js, and some change in this pushlog: https://hg.mozilla.org/projects/ux/pushloghtml?startID=450&endID=451 . Still no idea.

Comment 2

[:Gijs (he/him)]

So the private browsing tests quickly add and remove a bunch of windows. The last window that it closes somehow doesn't fire the CustomizableUI's unload listener, meaning we have a dead window hanging around, which breaks everything. I don't understand why the unload listener isn't firing - the registration code for the window does seem to run, and so an unload listener will have been registered in it.

Comment 3

[:Gijs (he/him)]

(In reply to :Gijs Kruitbosch from comment #2)
> So the private browsing tests quickly add and remove a bunch of windows. The
> last window that it closes somehow doesn't fire the CustomizableUI's unload
> listener,

s/The last window/some window/

In particular, the utility stuff for the private browsing test does: 

http://mxr.mozilla.org/mozilla-central/source/addon-sdk/source/test/private-browsing/windows.js#17

22   promise(win, 'DOMContentLoaded').then(function onload() {

If I s/DOMContentLoaded/load/, all the tests suddenly pass.

I'm guessing that because the load event hasn't fired, we don't get an unload event, either. However, that doesn't explain what commit in the pushlog suddenly triggered this to fail *everywhere*. That's a very surprising thing to have happen. Looks like I'll have to go and bisect that next... :-\

Comment 4

[:Gijs (he/him)]

(In reply to :Gijs Kruitbosch from comment #3)
> (In reply to :Gijs Kruitbosch from comment #2)
> > So the private browsing tests quickly add and remove a bunch of windows. The
> > last window that it closes somehow doesn't fire the CustomizableUI's unload
> > listener,
> 
> s/The last window/some window/
> 
> In particular, the utility stuff for the private browsing test does: 
> 
> http://mxr.mozilla.org/mozilla-central/source/addon-sdk/source/test/private-
> browsing/windows.js#17
> 
> 22   promise(win, 'DOMContentLoaded').then(function onload() {
> 
> If I s/DOMContentLoaded/load/, all the tests suddenly pass.
> 
> I'm guessing that because the load event hasn't fired, we don't get an
> unload event, either. However, that doesn't explain what commit in the
> pushlog suddenly triggered this to fail *everywhere*. That's a very
> surprising thing to have happen. Looks like I'll have to go and bisect that
> next... :-\

If I've not messed up, it seems I got lucky. This happened in the range	3eb8450ae7d6 to 14b57090e67e, inclusive. I suspect bug 862627, but I'll look closer before setting a dep.

Comment 5

[:Gijs (he/him)]

Confirmed via a local backout, this is because of bug 862627. I'll try to come up with a minimal testcase. In the meantime, Boris, do you have any idea why this sequence of events no longer produces unload events? (see comment #2 and comment #3)

Comment 6

[:Gijs (he/him)]

(In reply to :Gijs Kruitbosch from comment #5)
> I'll try to come up with a minimal testcase.

I've tried, but I'm failing. A port of bits of the private browsing test to mochitest (which wasn't as simple as I should have liked) didn't fail. Not entirely sure how to proceed from here.

Comment 7

[Boris Zbarsky [:bzbarsky]]

Bug 862627 would has three main effects:

1)  Exceptions that used to be silently swallowed are now reported to onerror handlers
    and the console.
2)  The relevant onerror handler is now the one of the window the function comes from,
    not the one the target comes from.
3)  The "window currently executing script" is the one the function comes from, not the
    one the target comes from.

In this case we're reaching the "function onload" bits, I assume, but just not firing unload on that window when it's closed?

Comment 8

[Boris Zbarsky [:bzbarsky]]

Oh, and I don't see why unload-firing per se would be affected, offhand.  :(

Comment 9

[:Gijs (he/him)]

(In reply to Boris Zbarsky [:bz] from comment #7)
> Bug 862627 would has three main effects:
> 
> 1)  Exceptions that used to be silently swallowed are now reported to
> onerror handlers
>     and the console.
> 2)  The relevant onerror handler is now the one of the window the function
> comes from,
>     not the one the target comes from.
> 3)  The "window currently executing script" is the one the function comes
> from, not the
>     one the target comes from.
> 
> In this case we're reaching the "function onload" bits, I assume, but just
> not firing unload on that window when it's closed?

That's what it looks like, yes. Note that the "function onload" bit is what gets called on the DOMContentLoaded event, not the load event.

Comment 10

[:Gijs (he/him)]

Local STR from $TOPSRCDIR of a copy of projects/ux:

1. cd addon-sdk/source/
(optional from here:

find test -iname 'test-*' | grep -v 'test-private-browsing' | grep -v 'ui-button' | xargs rm

or equivalent, as you only need private-browsing and ui-button - this will speed up running the tests.
)

2. bin/cfx testpkgs --binary $OBJDIR/dist/bin/firefox
or
bin/cfx testpkgs --binary $OBJDIR/dist/UX.app/Contents/MacOS/firefox

on OS X

Comment 11

[Legacy TBPL/Treeherder Robot]

Gijs
https://tbpl.mozilla.org/php/getParsedLog.php?id=28349276&tree=UX
WINNT 6.2 ux debug test jetpack on 2013-09-25 08:09:23
revision: 880516d00bfa
slave: t-w864-ix-124

TEST-UNEXPECTED-FAIL | tests/test-ui-button.test button added with resource URI | TypeError: aId is undefined
TypeError: aId is undefined
TEST-UNEXPECTED-FAIL | tests/test-ui-button.test button after destroy | TypeError: value is not a non-null object
TypeError: value is not a non-null object
TEST-UNEXPECTED-FAIL | tests/test-ui-button.test button icon set | TypeError: aId is undefined
TypeError: aId is undefined
TEST-UNEXPECTED-FAIL | tests/test-ui-button.test button multiple destroy | TypeError: aId is undefined
TypeError: aId is undefined
TEST-UNEXPECTED-FAIL | tests/test-ui-button.test button removed on dispose | TypeError: value is not a non-null object
TypeError: value is not a non-null object
TEST-UNEXPECTED-FAIL | tests/test-ui-button.test button removed on dispose | Timed out

Comment 12

[Boris Zbarsky [:bzbarsky]]

Note to self: the unload listener is added at http://hg.mozilla.org/projects/ux/file/0e19ff24a086/browser/components/customizableui/src/CustomizableUI.jsm#l740

Comment 13

[:Gijs (he/him)]

Further to comment #10, it seems that in addon-sdk/source/test/private-browsing/windows.js, you can remove everything but (the bottom copy of) testPerWindowPrivateBrowsingGetter, and in addon-sdk/source/test/test-private-browsing.js you can remove everything but the

 merge(module.exports, require('./private-browsing/windows'));

call. The problem is the specific testPerWindowPrivateBrowsingGetter test. Still not sure why, though.

Comment 14

[Boris Zbarsky [:bzbarsky]]

OK, so team-debugging with Gijs shows the following:

* The addon-sdk test in question adds a DOMContentLoaded listener that closes the window.
* The CustomizableUI stuff adds an unload listener when it sees a readystate transition
  to "complete".
* Forcing "indirect" to true in nsGlobalWindow::FinalClose makes the tests pass.

So here's what I think used to happen:

1)  DOMContentLoaded fired, called close() on the window.
2)  In FinalClose, "indirect" tested true, because we were inside an event listener for
    an event dispatched on the window being closed.
3)  We posted an nsCloseEvent.
4)  The nsCloseEvent fired.  Since "indirect" was true, it just posted another
    nsCloseEvent, with "indirect" set to false.
5)  readyState transitioned to "complete".  Unload listener added.
6)  nsCloseEvent fired, actually did the closing work, unload fired, listener triggered.

And here is what happens now:

1)  DOMContentLoaded fires, calls close() on the window.
2)  In FinalClose, "indirect" tests false, because we now use the JSContext of the
    listener, not the target, for event listeners.
3)  We posts an nsCloseEvent.
4)  The nsCloseEvent fires.  Since "indirect" is flse, we really close the window, fire
    unload.
5)  readyState transitions to "complete".  Unload listener added.

So the listener never gets called.

We should be able to fix this by changing the addon-sdk test to close the window off an event.  Or by registering the unload listeners earlier, perhaps?

Comment 15

[:Gijs (he/him)]

Attachment: don't re-add closed windows,

So I tried a bunch of magical ways of keeping track of unload. Either moving the registration forward into the actual toolbar constructor without waiting for readystate=complete, or using the window watcher/mediator. Nothing helped. Until I finally looked at the log again and realized that, if you see 2 register and 1 unregister call, then yes, the intuitive explanation is that there's an unregister call too little. But in this case, what happened was that we removed the build window from the map of known build windows, but from the closed window we still get another toolbar constructor event that fires and re-registers the same window, meaning we leak it. Adding a guard to check if the window is closed is enough to prevent this from happening.

Comment 16

[Boris Zbarsky [:bzbarsky]]

Comment on attachment 810142 [details] [diff] [review]
don't re-add closed windows,

Funtimes.  r=me

Comment 17

[:Gijs (he/him)]

https://hg.mozilla.org/projects/ux/rev/298db786a90b

Comment 18

[:Gijs (he/him)]

This seems gone, hurray!

Comment 19

[:Gijs (he/him)]

https://hg.mozilla.org/mozilla-central/rev/298db786a90b