1124217 - Spurious " JavaScript error: resource://app/modules/CustomizableUI.jsm, line 1575: TypeError: aWindowPalette is undefined" warnings in Talos runs

Status: RESOLVED FIXED

(Firefox :: Toolbars and Customization, defect, P4)

Description

[Ryan VanderMeulen [:RyanVM]]

This may be in other test suites as well, but it's definitely visible in Talos.

https://treeherder.mozilla.org/logviewer.html#?job_id=5711218&repo=mozilla-inbound

07:45:23 INFO - JavaScript error: resource://app/modules/WebappManager.jsm, line 44: NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIObserverService.removeObserver]
07:45:23 ERROR - JavaScript error: resource://app/modules/CustomizableUI.jsm, line 1575: TypeError: aWindowPalette is undefined

Comment 1

[:Gijs (he/him)]

When did this start?

Comment 2

[Ryan VanderMeulen [:RyanVM]]

On the push for bug 795981. Which is convenient, because I'm about to file another bug for mochitest-dt spam it caused too.

Comment 3

[Ryan VanderMeulen [:RyanVM]]

Oh interesting, we already have bug 1110110 for the "TypeError: this.inspector is null" logspam. From what I can tell, they went away for awhile and then resurfaced on the push for bug 795981 as well. Exciting.

Comment 4

[Justin Dolske [:Dolske]]

P5 based on user impact and it maybe not happening now?

Comment 5

[Ryan VanderMeulen [:RyanVM]]

Definitely is still. And still very much annoying and noisy.

Comment 6

[:Gijs (he/him)]

(In reply to Ryan VanderMeulen [:RyanVM UTC-5] from comment #2)
> On the push for bug 795981. Which is convenient, because I'm about to file
> another bug for mochitest-dt spam it caused too.

That bug didn't touch any of the relevant code here though... sounds like a race condition of sorts. It'd be kind of helpful if we had a stack here... it looks like the consumers are either customize mode or telemetry. The log link in comment #0 is dead, AFAICT this is the same: https://treeherder.mozilla.org/logviewer.html#?job_id=2162061&repo=fx-team but it only shows one of these, but I don't think any of the talos tests (apart from svgr because it runs the customization animation test) open customize mode. Which points to the telemetry consumer.

Mike, I'm going to assume that this is because aWindow.gNavToolbox.palette here:

http://mxr.mozilla.org/mozilla-central/source/browser/modules/BrowserUITelemetry.jsm#529

is null.

What should we be doing here and/or can/should we delay the telemetry call even more?

Comment 7

[:Gijs (he/him)]

Nudging this up considering it's still happening and annoying sheriffs.

Comment 8

[Mike Conley (:mconley) (:⚙️)]

Yeah, I guess the window is tearing down before the toolbar binding is running this bit:

https://hg.mozilla.org/mozilla-central/file/56492f7244a9/browser/components/customizableui/content/toolbar.xml#l74

The simplest solution might just be to null-check the gNavToolbox palette. If it's null, skip over the measurement.

Comment 9

[:Gijs (he/him)]

(In reply to Mike Conley (:mconley) - Needinfo me! from comment #8)
> Yeah, I guess the window is tearing down before the toolbar binding is
> running this bit:

That's odd though, AFAICT from the log the window isn't torn down? Unless this test, like other tests, does a single startup and exit to avoid "first run" stuff biasing the perf measurements?

> 
> https://hg.mozilla.org/mozilla-central/file/56492f7244a9/browser/components/
> customizableui/content/toolbar.xml#l74
> 
> The simplest solution might just be to null-check the gNavToolbox palette.
> If it's null, skip over the measurement.

If it really is window closure, I wonder if we shouldn't just skip all of this if window.closed .

Comment 10

[Mike Conley (:mconley) (:⚙️)]

We could do a try push and add some instrumentation to see what state the window is in? What do you think?

Comment 11

[:Gijs (he/him)]

(In reply to Mike Conley (:mconley) - Needinfo me! from comment #10)
> We could do a try push and add some instrumentation to see what state the
> window is in? What do you think?

Sounds good to me!

Comment 12

[Avi Halachmi (:avih)]

(In reply to :Gijs Kruitbosch from comment #6)
> ...but I don't think any of the talos tests
> (apart from svgr because it runs the customization animation test) open
> customize mode. Which points to the telemetry consumer.

s/svgr/CART/ but otherwise correct, no talos test opens customize mode except for CART.


(In reply to :Gijs Kruitbosch from comment #9)
> That's odd though, AFAICT from the log the window isn't torn down? Unless
> this test, like other tests, does a single startup and exit to avoid "first
> run" stuff biasing the perf measurements?

I don't think this bug is about any specific test. As far as I understand from comment 0, it sort of happens with all tests. We know it happens with the WebGL test (bug 1052467) where it started getting logged on 2015-03-05.

Also, All talos tests which use the "page load" framework/addon (tscrollx/tart/cart/tsvgx/tsvg_opacity/tp5o/tp5o_scroll) open and close a Firefox window quickly, and also have another window (I don't think it's a Firefox one) which stays open throughout the test run and AFAIK controls the main Firefox window which runs the tests/pages.

Joel if more familiar with this mechanism than myself.

Comment 13

[Joel Maher ( :jmaher ) (UTC -8)]

every single talos does does a warmup run to initialize the profile and preload whatever binaries.

regarding the pageloader addon (used by cart), there is a controlling xul window that launches a browser window where the testing takes place.

Comment 14

[:Gijs (he/him)]

I can repro this locally. I can confirm this is caused by the telemetry getter:

console.error:
  No window palette
console.trace:
_/CustomizableUI.jsm 1573 CustomizableUIInternal.getUnusedWidgets
_/CustomizableUI.jsm 3174 this.CustomizableUI.getUnusedWidgets
_wserUITelemetry.jsm 532 this.BrowserUITelemetry._getWindowMeasurements
_wserUITelemetry.jsm 291 this.BrowserUITelemetry._gatherFirstWindowMeasurements/<
_/nsSearchService.js 4150 onError
_/Promise-backend.js 870 Handler.prototype.process
_/Promise-backend.js 746 this.PromiseWalker.walkerLoop
_/Promise-backend.js 688 this.PromiseWalker.scheduleWalkerLoop/<

Looking into the 'why' now.

Comment 15

[:Gijs (he/him)]

Attachment: MozReview Request: bz://1124217/Gijs

/r/7119 - Bug 1124217 - don't gather telemetry for windows that have died, r?mconley

Pull down this commit:

hg pull -r e4b67a0c5c75fd9305b14669edf8e0edd0ab946f https://reviewboard-hg.mozilla.org/gecko/

Comment 16

[:Gijs (he/him)]

This patch fixes things for me locally.

Joel, I will just say though, that based on this:

(In reply to Joel Maher (:jmaher) from comment #13)
> every single talos does does a warmup run to initialize the profile and
> preload whatever binaries.


I would recommend that the warmup run should wait longer before killing off the browser it has created in order for this preloading and profile-initing to really happen. This error is caused because the process is nuked from orbit very very quickly.

Starting to do that will hopefully/maybe make numbers more stable in the long run, but might lead to numbers changing from their current baselines, so do this with care etc. needinfo on you to file any necessary followups / decide you don't want to do this.

Comment 17

[Joel Maher ( :jmaher ) (UTC -8)]

I am fine changing the warmup run to wait a bit longer, right now it loads up and executes some javascript, then quites- this is all in the 'onload' handler.

All of this was designed before we pulled things out of the initialization path.  how much longer should we wait?

Comment 18

[:Gijs (he/him)]

(In reply to Joel Maher (:jmaher) from comment #17)
> I am fine changing the warmup run to wait a bit longer, right now it loads
> up and executes some javascript, then quites- this is all in the 'onload'
> handler.
> 
> All of this was designed before we pulled things out of the initialization
> path.  how much longer should we wait?

Moved this discussion to bug 1155129.

Comment 19

[Mike Conley (:mconley) (:⚙️)]

Comment on attachment 8593308 [details]
MozReview Request: bz://1124217/Gijs

https://reviewboard.mozilla.org/r/7117/#review5913

Thanks, Gijs!

::: browser/modules/BrowserUITelemetry.jsm
(Diff revision 1)
> +      this._firstWindowMeasurements = win && !win.closed ? this._getWindowMeasurements(win, rv)
> -                                          : {};
> +                                                         : {};

I think this could be made slightly more readable:

```
let hasWindow = win && !win.closed;
this._firstWindowMeasurements = hasWindow ? this._getWindowMeasurements(win, rv)
                                          : {};
```

Comment 20

[Pulsebot]

https://hg.mozilla.org/integration/fx-team/rev/0f274d210b8a

Comment 21

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/0f274d210b8a

Comment 22

[Ryan VanderMeulen [:RyanVM]]

Please nominate this for Aurora/Beta approval.

Comment 23

[:Gijs (he/him)]

Comment on attachment 8593308 [details]
MozReview Request: bz://1124217/Gijs

Approval Request Comment
[Feature/regressing bug #]: n/a
[User impact if declined]: talos and maybe some test logs are filled with useless stuff
[Describe test coverage new/current, TreeHerder]: nope
[Risks and why]: very low, essentially an "is this window closed" check was added before trying to get info. This may affect telemetry output we see on the relevant servers - but it should be in a good way!
[String/UUID change made/needed]: nope

Comment 24

[Sylvestre Ledru [:Sylvestre]]

Comment on attachment 8593308 [details]
MozReview Request: bz://1124217/Gijs

Should be in 38 beta 6.

Comment 25

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/20ce52f8b7bc

Comment 26

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-beta/rev/849bf3c58408

Comment 28

[:Gijs (he/him)]

Attachment: MozReview Request: Bug 1124217 - don't gather telemetry for windows that have died, r?mconley