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

RESOLVED FIXED in Firefox 38

Status

()

defect
P4
normal
RESOLVED FIXED
5 years ago
4 years ago

People

(Reporter: RyanVM, Assigned: Gijs)

Tracking

(Blocks 1 bug)

unspecified
Firefox 40
Points:
2
Dependency tree / graph
Bug Flags:
firefox-backlog +
in-testsuite +
qe-verify -

Firefox Tracking Flags

(firefox38 fixed, firefox39 fixed, firefox40 fixed)

Details

Attachments

(1 attachment, 1 obsolete attachment)

Reporter

Description

5 years ago
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
Assignee

Comment 1

5 years ago
When did this start?
Flags: needinfo?(ryanvm)
Reporter

Comment 2

5 years ago
On the push for bug 795981. Which is convenient, because I'm about to file another bug for mochitest-dt spam it caused too.
Blocks: 795981
Flags: needinfo?(ryanvm)
Reporter

Comment 3

5 years ago
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.
P5 based on user impact and it maybe not happening now?
Priority: -- → P5
Reporter

Comment 5

4 years ago
Definitely is still. And still very much annoying and noisy.
Assignee

Comment 6

4 years ago
(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?
Flags: needinfo?(mconley)
Assignee

Comment 7

4 years ago
Nudging this up considering it's still happening and annoying sheriffs.
Priority: P5 → P4
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.
Flags: needinfo?(mconley)
Assignee

Comment 9

4 years ago
(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 .
We could do a try push and add some instrumentation to see what state the window is in? What do you think?
Flags: needinfo?(gijskruitbosch+bugs)
Assignee

Comment 11

4 years ago
(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!
Flags: needinfo?(gijskruitbosch+bugs)
(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.
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.
Blocks: 1052467
Assignee

Updated

4 years ago
Flags: needinfo?(gijskruitbosch+bugs)
Assignee

Comment 14

4 years ago
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.
Assignee

Comment 15

4 years ago
/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/
Attachment #8593308 - Flags: review?(mconley)
Assignee

Comment 16

4 years ago
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.
Assignee: nobody → gijskruitbosch+bugs
Status: NEW → ASSIGNED
Flags: qe-verify-
Flags: needinfo?(jmaher)
Flags: needinfo?(gijskruitbosch+bugs)
Flags: in-testsuite+
Flags: firefox-backlog+
Assignee

Updated

4 years ago
Iteration: --- → 40.2 - 27 Apr
Points: --- → 2
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?
Flags: needinfo?(jmaher)
Assignee

Comment 18

4 years ago
(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 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)
                                          : {};
```
Attachment #8593308 - Flags: review?(mconley) → review+
Reporter

Comment 21

4 years ago
https://hg.mozilla.org/mozilla-central/rev/0f274d210b8a
Status: ASSIGNED → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 40
Reporter

Comment 22

4 years ago
Please nominate this for Aurora/Beta approval.
Flags: needinfo?(gijskruitbosch+bugs)
Assignee

Comment 23

4 years ago
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
Flags: needinfo?(gijskruitbosch+bugs)
Attachment #8593308 - Flags: approval-mozilla-beta?
Attachment #8593308 - Flags: approval-mozilla-aurora?
Comment on attachment 8593308 [details]
MozReview Request: bz://1124217/Gijs

Should be in 38 beta 6.
Attachment #8593308 - Flags: approval-mozilla-beta?
Attachment #8593308 - Flags: approval-mozilla-beta+
Attachment #8593308 - Flags: approval-mozilla-aurora?
Attachment #8593308 - Flags: approval-mozilla-aurora+
Assignee

Comment 27

4 years ago
Attachment #8593308 - Attachment is obsolete: true
Attachment #8619190 - Flags: review+
You need to log in before you can comment on or make changes to this bug.