1509755 - Intermittent failure caused by ASRouterTriggerListeners.init() potentially accessing win.gBrowser before DOMContentLoaded has run

Status: RESOLVED FIXED

(Firefox :: New Tab Page, defect, P1)

Description

[(no longer active)]

I hit this intermittent test failure in a new test that I added on try today:

https://taskcluster-artifacts.net/KMsDrB9MTtiC63yvDVfkbQ/0/public/logs/live_backing.log

23:18:35     INFO - TEST-UNEXPECTED-FAIL | browser/modules/test/browser/browser_UsageTelemetry_uniqueOriginsVisitedInPast24Hours.js | A promise chain failed to handle a rejection: win.gBrowser is undefined; can't access its "addTabsProgressListener" property - stack: init@resource://activity-stream/lib/ASRouterTriggerListeners.jsm:43:11
23:18:35     INFO - loadMessagesFromAllProviders@resource://activity-stream/lib/ASRouter.jsm:406:52
23:18:35     INFO - async*init@resource://activity-stream/lib/ASRouter.jsm:449:11
23:18:35     INFO - async*enable@resource://activity-stream/lib/ASRouterFeed.jsm:15:13
23:18:35     INFO - async*onAction@resource://activity-stream/lib/ASRouterFeed.jsm:32:9
23:18:35     INFO - _middleware/</<@resource://activity-stream/lib/Store.jsm:51:11
23:18:35     INFO - Store/this[method]@resource://activity-stream/lib/Store.jsm:29:54
23:18:35     INFO - init@resource://activity-stream/lib/Store.jsm:140:7
23:18:35     INFO - async*init@resource://activity-stream/lib/ActivityStream.jsm:338:7
23:18:35     INFO - onBrowserReady@resource:///modules/AboutNewTab.jsm:64:7
23:18:35     INFO - observe/<@resource:///modules/AboutNewTab.jsm:111:48
23:18:35     INFO - Rejection date: Sun Nov 25 2018 23:18:33 GMT+0000 (Greenwich Mean Time) - false == true - JS frame :: resource://testing-common/PromiseTestUtils.jsm :: assertNoUncaughtRejections :: line 257
23:18:35     INFO - Stack trace:
23:18:35     INFO - resource://testing-common/PromiseTestUtils.jsm:assertNoUncaughtRejections:257
23:18:35     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1118
23:18:35     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1084
23:18:35     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:982
23:18:35     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:803

What this test is doing is quite simple:
https://hg.mozilla.org/try/rev/1ca1b2ddb66807ce6d7b86367d8e3ff1c35984af#l3.20

It is opening a new window and loading a few tabs in it.  If you look at the screenshot <https://taskcluster-artifacts.net/KMsDrB9MTtiC63yvDVfkbQ/0/public/test_info/mozilla-test-fail-screenshot_eunnfw.png> you will note that this is happening quite early in the startup, before we have even had time to put the window completely on the screen.

After some time looking around at the code, here is my hypothesis as to what is happening.

Note that the test is running in --verify mode here.  So the browser is starting up, and right away we're starting to run the test.  This needs to happen very fast, before browser.xul in the second window fully initializes.

As the test is running, the browser finishes its initialization, and sessionstore-windows-restored gets dispatched.  That triggers this callback, which is running in response to the *main* browser session initializing!  This is the root of our call stack.  Then we end up initializing a bunch of lazy-inited stuff until we get to this code: <https://searchfox.org/mozilla-central/rev/f997bd6bbfc4773e774fdb6cd010142370d186f9/browser/components/newtab/lib/ASRouterTriggerListeners.jsm#43>

I don't know what this code exactly depends on running, but I think the main thing that it is being confused on is which window has just been initialized.  As a result we go ahead and access win.gBrowser, but this happens before <https://searchfox.org/mozilla-central/rev/f997bd6bbfc4773e774fdb6cd010142370d186f9/browser/base/content/browser.js#1334> has run, so we end up with an intermittent failure.

Note that this can bite any test which ends up opening a window shortly after the browser startup.  A quick search on Bugzilla shows 14 intermittent bugs on file about this issue.  I believe fixing this can fix them all in one go, so I'm setting up dependencies.

Comment 1

[GitHub Bugzilla PR Linker]

Attachment: Link to GitHub pull-request: https://github.com/mozilla/activity-stream/pull/4580

Comment 2

[[github robot]]

Commit pushed to master at https://github.com/mozilla/activity-stream

https://github.com/mozilla/activity-stream/commit/abb7a49a255dea987e1659df618526585a90d48c
Fix Bug 1509755 - Wait for browser initialization to finish before adding CFR trigger listeners (#4580)

Comment 3

[Ed Lee :Mardak]

https://hg.mozilla.org/mozilla-central/rev/8de26a67ac5c