1387852 - The New Tab doesn't load (probably upon a session restore) unless you reload the tab

Status: VERIFIED FIXED

(Firefox :: New Tab Page, defect)

Description

[Itiel]

Environment:
Windows 10 x86
Latest Nightly (57.0a1 2017-08-06), with about ~260 tabs, most of them are in the background (some about:config entries [1] are enabled)

It started to happen in the last 2-3 days.
Upon closing Nightly I always get the "Do you want to save your session?" dialog (see [1]). After saving the session and rebooting Nightly, opening the New Tab will result in a (completely) blank page.
Right clicking everywhere > Inspect Element will give me the following:
ReferenceError: addMessageListener is not defined

And after expanding it:
activity-stream.bundle.js:736:3
initStore
resource://activity-stream/data/content/activity-stream.bundle.js:736:3
<anonymous>
resource://activity-stream/data/content/activity-stream.bundle.js:2724:15
__webpack_require__
resource://activity-stream/data/content/activity-stream.bundle.js:20:12
<anonymous>
resource://activity-stream/data/content/activity-stream.bundle.js:66:18
<anonymous>
resource://activity-stream/data/content/activity-stream.bundle.js:1:11

Reloading the New Tab page fixes it.

For some reason if the last opened tab before I save the session and reboot Nightly is the New Tab, the issue will not reproduce.

I've tried reproducing it on a new profile but it looks fine (also after applying the about:config entires).
Can't try to pinpoint the regression range as Mozregression doesn't work with the latest Nightly builds for some reason.


[1] https://support.mozilla.org/he/questions/1060179#answer-724117

Comment 1

[Ed Lee :Mardak]

Should be fixed in today's nightly with bug 1386445

Comment 2

[Ed Lee :Mardak]

Actually, your nightly (57.0a1 2017-08-06) seems like it should have the commit included... https://hg.mozilla.org/mozilla-central/rev/b48486fff521

Comment 3

[Itiel]

Maybe this would help?
https://perfht.ml/2fk0W3G
Taken from when this issue occurs.

Comment 4

[Ed Lee :Mardak]

Did the problem already happen? That profile log seems to show a new tab being opened. Are you saying a restored tab is giving the the "addMessageListener is not defined" error or that opening a new tab after a sessionstore results in a blank page?

Comment 5

[Itiel]

(In reply to Ed Lee :Mardak from comment #4)
> Did the problem already happen? That profile log seems to show a new tab
> being opened. Are you saying a restored tab is giving the the
> "addMessageListener is not defined" error or that opening a new tab after a
> sessionstore results in a blank page?

The order of actions were:
1. Launch Nightly (from a session restore) where the first-focused tab was NOT a new tab
2. Start the profiler
3. Open a new tab - it was blank
4. Refresh that new tab - now works correctly
5. Capture Profile from the profiler

Opening a new tab AFTER the session restore results a blank page, and from the inspector I can see the "addMessageListener is not defined" error.

Comment 6

[Ed Lee :Mardak]

If you can consistently reproduce this, could you start Firefox with the profiler?

E.g.,

MOZ_PROFILER_STARTUP=1 ./mach run

Or probably

MOZ_PROFILER_STARTUP=1 …/firefox-bin

Also if possible, increase the profile resolution from the default 1ms.

Comment 7

[Itiel]

(In reply to Ed Lee :Mardak from comment #6)
> If you can consistently reproduce this, could you start Firefox with the
> profiler?
> 
> E.g.,
> 
> MOZ_PROFILER_STARTUP=1 ./mach run
> 
> Or probably
> 
> MOZ_PROFILER_STARTUP=1 …/firefox-bin
> 
> Also if possible, increase the profile resolution from the default 1ms.

Gladly, but I'm running Windows 10. Is it possible on this platform?

Comment 8

[Itiel]

Another profile with 10ms profile resolution, taken with the same steps from comment 5:
https://perfht.ml/2fkwiY3

Comment 9

[Ed Lee :Mardak]

It's been a while since I've tried, but if you open up the cmd/command line and cd to the directory with Firefox (firefox.exe):

set MOZ_PROFILER_STARTUP=1
firefox.exe

Comment 10

[Itiel]

(In reply to Ed Lee :Mardak from comment #9)
> It's been a while since I've tried, but if you open up the cmd/command line
> and cd to the directory with Firefox (firefox.exe):
> 
> set MOZ_PROFILER_STARTUP=1
> firefox.exe

Here goes:
https://perfht.ml/2fjij4J

Comment 11

[Ed Lee :Mardak]

Great! Thanks. I'll take a look. A couple questions:

Do you have either or both about:config prefs browser.sessionstore.restore_on_demand and browser.sessionstore.restore_tabs_lazily set to false? (Looks like both are probably set to true.)
What did you do after opening the tab and seeing it blank? Did you close it before ending the profile? (Looks like you opened the profile dialog from the blank tab.)

Some initial notes:

sss_init of nsSessionStartup.js at T+0.279s
starts reading in the session file…

BG_beforeUIStartup of nsBrowserGlue.js at T+0.284s
calls down to SessionStore.init

_delayedStartup of browser.js at T+0.728s
AboutNewTab is loaded at T+0.730s

_onSessionFileRead of nsSessionStartup.js T+1.338s
starts restoring tabs…

onBeforeBrowserWindowShown of SessionStore at at T+1.397s
calls down to numerous tabbrowser.addTab at T+1.402s

onBrowserReady of activity-stream bootstrap.js at T+2.131s

new tab opened at T+12.308s
initPort of RemotePageManager.jsm at T+13.071s
onNewTabLoad of ActivityStreamMessageChannel.jsm at T+13.684s
received NewTabUtils…getTopSites for getLinksWithDefaults of TopSitesFeed.jsm at T+14.021s

probably for the preloaded browser:
got another initPort at T+15.010s
got another onNewTabLoad at T+15.100s

received some activity-stream content message at T+15.276s

some popup is open (maybe the profiler dialog?) at T+16.667s

received another activity-stream content message at T+17.157s

Those last two content messages are most likely SAVE_SESSION_PERF_DATA where potentially the first loaded about:newtab didn't have addMessageListener available yet and wasn't visible, so initStore fails but DetectUserSessionStart runs on visibility change.

My guess is the first content message is from the actually opened tab for visibility_event_rcvd_ts. And the second content message is from the preloaded browser where topsites_first_painted_ts gets sent when preloaded but visibility only happens on visible.

dmose,k88hudson: Does that seem accurate? tl;dr: My current guess is the page somehow loaded without addMessageListener available in the process of opening a not-preloaded about:newtab. By the time it did become visible, it was able to sendAsyncMessage the visibility event. If that's actually the case, unless we can figure out why RemotePageManager (or related) isn't setting addMessageListener early enough, it should just try addMessageListener again after a tick (and again? until success?)

Comment 12

[Dan Mosedale (:dmosedale, :dmose)]

Going to the Markers View, and entering UserTiming in the "Filter Markers" box yields some interesting stuff.

The main thread has browser-open-newtab-start at 12.307.  That can only come from user action, so that's when the first newtab was opened by hand.

Content process 1 is weird.  It has two blocks of topsites_first_painted_ts, one starting at 15.155 and the other starting at 17.156.  Those correspond to the two messages that Ed mentions above.  Presumably one of these is the preloaded new tab (which wouldn't have a visibility_event_rcvd_ts, since it's not yet visable), and the other is the refresh of the initial busted tab (which should have a visibility_event_rcvd_ts but doesn't).

Looking at content process 2, we see a visibility_event_rcvd_ts at 12.314, which corresponds very closely to that browser-open-newtab-start, which we've been told is busted.  And there's a second at 15.090, which is just before the topsites paint that happens in content process 1.  Huh?  Is it possible for a tab to be moved between content processes?

So I think this modifies your hypothesis some, but I'm not yet sure where it leaves us...

Comment 13

[Dan Mosedale (:dmosedale, :dmose)]

I've filed [the bug that's causing the extra topsites_first_painted_ts](https://github.com/mozilla/activity-stream/issues/3105).

Comment 14

[Ed Lee :Mardak]

Oh duh. Completely forgot about looking at the content process profile.

Searching for "(root scope) resource://activity-stream/data/content/activity-stream.bundle.js" gets the bundle loading.

Content process 1:
13.578s: loads the bundle
13.702s: get first main to content message

Content process 2:
 2.525s: loads the bundle
12.314s: visibility change -> mark visibility_event_rcvd_ts
15.086s: loads the bundle
15.090s: mark visibility_event_rcvd_ts (already visible)
15.104s: gets first main to content message

Not sure why content process 2 is loading activity stream at 2.525s.. but here's near the first activity of process 2:
 2.153s mainproc: getWindow resource://gre/modules/HiddenFrame.jsm called by addon-sdk window.js
 2.155s content2: (root scope) jar:file:///C:/Program%20Files/Nightly/omni.ja!/components/extension-process-script.js
 2.213s content2: loadURI chrome://global/content/browser-child.js

For activity stream to "get first message" it must have been able to addMessageListener. So the only one missing seems to be the early 2.525s content process 2 loading of activity stream bundle. This also matches up with content 2 marking visibility_event_rcvd_ts as that event listener is added before initStore throws for not having addMessageListener.

Although it doesn't make sense why there's two visibility_event_rcvd_ts on opening one tab.

Comment 15

[Ed Lee :Mardak]

ItielMaN, can you try 2 things for me:

1) on the blank new tab page, open the web console and type "window.addMessageListener" and press enter. Does it say "undefined" or "function addMessageListener()"

If it does say "function", could you do this second step:

2) run Firefox from the target.zip for this build:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=21e9938d5623512e23c5e6d011626623607beab1&filter-searchStr=build&selectedJob=121305680

direct link to target.zip: https://queue.taskcluster.net/v1/task/LLSPEz-IRKei25zZAsfDcw/runs/0/artifacts/public/build/target.zip

That's a build from the latest mozilla-central with additional logging when it tries to addMessageListener:

https://hg.mozilla.org/try/rev/36cd293a32ac6aa9399dc2f68bcb135e0a5a7250

It should print out something like this in the console:

> init 104.655 1502067550232 true true function activity-stream.bundle.js:751:1
> 2.init 106.8 1502067550235 true false function activity-stream.bundle.js:751:1
> promise 113.47 1502067550241 true false function activity-stream.bundle.js:751:1
> 2.promise 113.94500000000001 1502067550242 true false function activity-stream.bundle.js:751:1
> request 114.36500000000001 1502067550242 true false function activity-stream.bundle.js:751:1
> 2.request 114.61500000000001 1502067550242 true false function activity-stream.bundle.js:751:1
> timeout 163.29 1502067550291 true false function activity-stream.bundle.js:751:1
> 2.timeout 163.615 1502067550291 true false function activity-stream.bundle.js:751:1

Comment 16

[Ed Lee :Mardak]

Pretty sure Content 1 is the preloaded browser, so that also seems to match up with the lack of visibility event there.

Taking a closer look at the topsites_first_painted_ts markers in Content 1:

15.155
15.155
15.155
15.156
15.156

then

17.156
17.157
17.157
17.158
17.158
17.159
17.160
17.161

And if I search the call stack for times of nsRefreshDriver::Tick the first one is 14.155.

Those numbers seem awfully suspiciously close to 1 or 2 seconds differences. Probably because it's not visible and requestAnimationFrame is throttled to 1 per second.

Comment 17

[Itiel]

(In reply to Ed Lee :Mardak from comment #11)
> Great! Thanks. I'll take a look. A couple questions:
> 
> Do you have either or both about:config prefs
> browser.sessionstore.restore_on_demand and
> browser.sessionstore.restore_tabs_lazily set to false? (Looks like both are
> probably set to true.)
> What did you do after opening the tab and seeing it blank? Did you close it
> before ending the profile? (Looks like you opened the profile dialog from
> the blank tab.)

Both prefs are set to true.
I've reloaded the new tab page about a second or so after I saw it blank.
And no, I ended the profiling only after I saw the new tab page rendered correctly (and that was, as said, after reloading the busted new tab page).

(In reply to Ed Lee :Mardak from comment #15)
> ItielMaN, can you try 2 things for me:
> 
> 1) on the blank new tab page, open the web console and type
> "window.addMessageListener" and press enter. Does it say "undefined" or
> "function addMessageListener()"
> 
> If it does say "function", could you do this second step:

Nothing happens after I press enter. Not even "undefined".
Though, in the autocomplete list I do not see it as a suggestion.
After reloading the new tab page (and seeing the page load correctly), the "window.addMessageListener" is suggested and I do see "function addMessageListener()" after pressing enter.

Do I still need to run your build?

Comment 18

[Ed Lee :Mardak]

(In reply to ItielMaN from comment #17)
> I've reloaded the new tab page about a second or so after I saw it blank.
Oh. That changes… /everything/! Well maybe. It does explain some stuff, but I'll need to take a closer look in the morning.

> Nothing happens after I press enter. Not even "undefined".
> Though, in the autocomplete list I do not see it as a suggestion.
> After reloading the new tab page (and seeing the page load correctly), the
> "window.addMessageListener" is suggested and I do see "function
> addMessageListener()" after pressing enter.
> 
> Do I still need to run your build?
Thanks for confirming. No you won't need to run the build as it won't fix the problem if addMessageListener doesn't even appear after typing it in. This means the page doesn't get hooked up for messages for some reason.

Comment 19

[Ed Lee :Mardak]

It sounds like this is pretty consistent on each restart. Could you try turning off your add-ons and see if that affects things?

Comment 20

[Itiel]

(In reply to Ed Lee :Mardak from comment #19)
> It sounds like this is pretty consistent on each restart. Could you try
> turning off your add-ons and see if that affects things?

Tried that yesterday, and also now after updating Nightly to 2017-08-07. Same result.

Comment 21

[Itiel]

Okay, so this is most probably 100% firefox at fault and because of other environmental reasons (broken profile, addons etc).
Just tried running 56.0a1 (2017-07-23) with the same profile I'm having and it works smoothly.
It's an ant work but I'm trying now to run every Nightly (manually! Mozregression isn't working for latest Nightlies. At least on Windows) to see what is the regression range.

Comment 22

[Itiel]

(In reply to ItielMaN from comment #21)
> Okay, so this is most probably 100% firefox at fault and because of other
> environmental reasons (broken profile, addons etc).

What did I say here? lol
I meant that I ruled out everything else (as the same profile is used with an older 56.0a1 and the new tab load just fine, plus I've already tried running Nightly in safe mode).

Anyway, the regression range is 2017-08-02 to 2017-08-03.
Investigating further...

Comment 23

[Itiel]

2017-08-07T19:41:50: DEBUG : Using url: https://hg.mozilla.org/integration/autoland/json-pushes?changeset=ae8bd889b02d932210c1dd101ddd39a3619bc3cc&full=1
2017-08-07T19:41:51: DEBUG : Found commit message:
Bug 1385090 - Pass Remote Pages instance from AboutNewTab on override r=mossop

MozReview-Commit-ID: 7oBsmIUpQXs

2017-08-07T19:41:51: INFO : The bisection is done.
2017-08-07T19:41:51: INFO : Stopped

Comment 24

[Ed Lee :Mardak]

What happens before that change? The first opened new tab shows activity stream content?

Comment 25

[Ed Lee :Mardak]

ahillier, the regression is from bug 1385090.

ItielMaN, can you restart Firefox where it's broken and *without* opening a new tab:

1) go to about:addons
2) open the web console
3) copy/paste the below then hit enter

console.log("preloaded?", Services.wm.getMostRecentWindow("navigator:browser").gBrowser._preloadedBrowser)

Comment 26

[Itiel]

(In reply to Ed Lee :Mardak from comment #24)
> What happens before that change? The first opened new tab shows activity
> stream content?

Yup.

(In reply to Ed Lee :Mardak from comment #25)
> ahillier, the regression is from bug 1385090.
> 
> ItielMaN, can you restart Firefox where it's broken and *without* opening a
> new tab:
> 
> 1) go to about:addons
> 2) open the web console
> 3) copy/paste the below then hit enter
> 
> console.log("preloaded?",
> Services.wm.getMostRecentWindow("navigator:browser").gBrowser.
> _preloadedBrowser)

This is the result:
preloaded? 
<browser type="content" message="true" messagemanagergroup="browsers" contextmenu="contentAreaContextMenu" tooltip="aHTMLTooltip" remoteType="web" remote="true" selectmenulist="ContentSelectDropdown" datetimepicker="DateTimePickerPanel" autoscrollpopup="autoscroller" nodefaultsrc="true" clickthrough="never">

And right after that, in a new line I see:
undefined

Comment 27

[Ed Lee :Mardak]

(In reply to ItielMaN from comment #26)
> preloaded? <browser type="content" message="true" messagemanagergroup="browsers"
Interesting…

Looks like in the profile, while sessionstore is adding tabs, it triggers the logic to preload the browser.

T+0.730s: AboutNewTab loaded
T+1.983s: _createPreloadedBrowser from addTab from sessionstore
T+2.131s: activity stream loaded in main
T+2.280s: react.js loaded in preloaded browser content process 2
T+2.288s: react-dom.js loaded
T+2.355s: react-intl.js loaded
T+2.477s: redux.js loaded
T+2.535s: activity-stream.bundle.js loaded

I would guess the "addMessageListener" fails at this time. Unclear why it doesn't exist in that scope though…

Comment 28

[Itiel]

If that helps, I've noticed that if save the session *while the new tab is the active tab*, close Nightly and restart back, the New Tab that automatically opens is functioning correctly, but if I open *another* new tab, it's all over again. This second new tab would be blank and with the "addMessageListener is not defined" error. Reloading this second new tab or opening other new tabs would work correctly.

Comment 30

[Ed Lee :Mardak]

With bug 1389701 fixed, can you reproduce this issue?

Comment 31

[Itiel]

(In reply to Ed Lee :Mardak (PTO Aug 12 - Aug 20) from comment #30)
> With bug 1389701 fixed, can you reproduce this issue?

Nope.

Comment 32

[Ed Lee :Mardak]

Thanks for the profiles and help debugging this. https://hg.mozilla.org/mozilla-central/rev/e81a6f33863a