1396071 - browser_ext_devtools_inspectedWindow.js is going to frequently fail when Gecko 57 merges to Beta on 2017-09-20

Status: VERIFIED FIXED

(DevTools :: General, defect)

Description

[Ryan VanderMeulen [:RyanVM]]

[Tracking Requested - why for this release]: Frequently failing test on the next merge day.

I won't call this permafail since I'm pretty sure there were *some* green runs, but the failure rate is extremely high nonetheless (intermittently green more than the other way around).

I bisected this down to the range below:
https://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=a2723b650460&tochange=e4b8ea7baeb6

From there, bug 1395262 seems like the most obvious candidate within the range, but I haven't actually verified that. Regardless, can you please take a look, Tom? CCing Luca as well just in case he has any ideas.

https://treeherder.mozilla.org/logviewer.html#?job_id=127609175&repo=try

TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_devtools_inspectedWindow.js | Got exceptionInfo.value value Error: fake eval exception
	@debugger eval called from moz-extension://b18d9dca-ab60-4f95-aea8-119930c216c9/ - eval code:1:7
 matches /Error: fake eval exception\n.*moz-extension:\/\// - 
Console message: [JavaScript Error: "TypeError: this._urls is null" {file: "resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/client/framework/source-map-url-service.js" line: 82}]
Buffered messages finished
TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_devtools_inspectedWindow.js | A promise chain failed to handle a rejection: this._urls is null - stack: null
Rejection date: Fri Sep 01 2017 02:30:13 GMT+0000 (UTC) - false == true - JS frame :: resource://testing-common/PromiseTestUtils.jsm :: assertNoUncaughtRejections :: line 265
Stack trace:
    resource://testing-common/PromiseTestUtils.jsm:assertNoUncaughtRejections:265
    chrome://mochikit/content/browser-test.js:Tester_execTest/<:825
    Tester_execTest@chrome://mochikit/content/browser-test.js:794:9
    Tester.prototype.nextTest</<@chrome://mochikit/content/browser-test.js:694:7
    SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:795:59
Leaving test bound test_devtools_inspectedWindow_eval

The patch below should be sufficient for reproducing locally or on Try. Let me know if it doesn't work.
https://hg.mozilla.org/try/rev/893117049f14004a416aad09dabe24ea2f5d5ef2

Comment 1

[Julian Descottes [:jdescottes]]

Attachment: Bug 1396071 - check if SourceMapURLService has been destroyed after async call;

Review commit: https://reviewboard.mozilla.org/r/175598/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/175598/

Comment 2

[Julian Descottes [:jdescottes]]

For the record we have a similar intermittent that appeared for scratchpad : https://bugzilla.mozilla.org/show_bug.cgi?id=1395783

I guess the most probable explanation for the failure is related to an async step in the constructor of the SourceMapURLService:

>  this._loadingPromise = threadClient.getSources().then(({sources}) => {
>    // Ignore errors.  Register the sources we got; we can't rely on
>    // an event to arrive if the source actor already existed.
>    for (let source of sources) {
>      this._onSourceUpdated(null, {source});
>    }
>  }, e => {
>    // Also ignore any protocol-based errors.
>  });

If the toolbox is destroyed before threadClient.getSources() finishes, it will trigger the error detected in the test. No idea why this would be more frequent on Beta than on Nightly, and I can't reproduce locally for now.

This code was added by Bug 1396071, that landed on central yesterday: https://hg.mozilla.org/mozilla-central/rev/fcd4aabcec11 
It landed prior to the bisect mentioned above, so it's possible that another changeset increased the intermittent frequency.

I attached a patch here that should avoid the failure, but we should really try to understand why this fails particularly on beta (if anyone can repro locally and make progress feel free to discard my patch). Try at https://treeherder.mozilla.org/#/jobs?repo=try&revision=aa04831d330ea3b383eb443c2edc4c0e67bc94e1

Comment 3

[Julian Descottes [:jdescottes]]

My previous try push was probably a bit bad, here is another one based on : https://hg.mozilla.org/try/rev/4a8fb30e31ab51f9d4cc546b038180041966d8cf

https://treeherder.mozilla.org/#/jobs?repo=try&revision=a395adfb3cb343a2b124c7e78cce2f53fc2a30c9

No failure for browser_ext_devtools_inspectedWindow.js spotted so far.

Comment 4

[Ryan VanderMeulen [:RyanVM]]

Comment on attachment 8903831 [details]
Bug 1396071 - check if SourceMapURLService has been destroyed after async call;

I included it with my Try runs last night and it looks good there too.

Comment 5

[Tom Tromey :tromey]

Comment on attachment 8903831 [details]
Bug 1396071 - check if SourceMapURLService has been destroyed after async call;

https://reviewboard.mozilla.org/r/175598/#review181276

r+ with the comment addressed.  Thank you very much for doing this.

::: devtools/client/framework/source-map-url-service.js:40
(Diff revision 1)
>  
>    Services.prefs.addObserver(SOURCE_MAP_PREF, this._onPrefChanged);
>  
>    // Start fetching the sources now.
>    this._loadingPromise = threadClient.getSources().then(({sources}) => {
> +    if (this._destroyed) {

Elsewhere, `this._urls` is used as a sentinel for "destroyed":

https://dxr.mozilla.org/mozilla-central/rev/632e42dca494ec3d90b70325d9c359f80cb3f38a/devtools/client/framework/source-map-url-service.js#105

So I don't think a new flag is needed.

I think it's fine to land this though I do wonder what is going on.  Is it just a normal race?  Or is the service being started unnecessarily at some spot?

Comment 6

[Julian Descottes [:jdescottes]]

Comment on attachment 8903831 [details]
Bug 1396071 - check if SourceMapURLService has been destroyed after async call;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/175598/diff/1-2/

Comment 7

[Julian Descottes [:jdescottes]]

Comment on attachment 8903831 [details]
Bug 1396071 - check if SourceMapURLService has been destroyed after async call;

https://reviewboard.mozilla.org/r/175598/#review181276

> Elsewhere, `this._urls` is used as a sentinel for "destroyed":
> 
> https://dxr.mozilla.org/mozilla-central/rev/632e42dca494ec3d90b70325d9c359f80cb3f38a/devtools/client/framework/source-map-url-service.js#105
> 
> So I don't think a new flag is needed.
> 
> I think it's fine to land this though I do wonder what is going on.  Is it just a normal race?  Or is the service being started unnecessarily at some spot?

Thanks for the review! Good point about using this._urls. I also moved the guard inside of the _onSourceUpdated method, it's also more consistent with the rest of the file.

Regarding the increased frequency on Beta I have no idea how to explain that. The only thing I can think of is that the old console is being used instead of the new console on Beta. But as I said I can't reproduce locally for now :(

Comment 8

[Tom Tromey :tromey]

Clearing NI.

Comment 9

[Ryan VanderMeulen [:RyanVM]]

Comment on attachment 8903831 [details]
Bug 1396071 - check if SourceMapURLService has been destroyed after async call;

Looks good on Try!

Comment 10

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/4ef59b77d1cb
check if SourceMapURLService has been destroyed after async call;r=tromey

Comment 11

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/4ef59b77d1cb