1389701 - Newly loaded child RemotePageManager can register pages too late to properly manage created documents

Status: RESOLVED FIXED

(Firefox :: New Tab Page, defect)

Description

[Ed Lee :Mardak]

In the process of investigating bug 1382373, I made a video from holding cmd-T and noticed some tabs ended up erroring:

JavaScript error: resource://activity-stream/data/content/activity-stream.bundle.js, line 754: ReferenceError: addMessageListener is not defined

This is well after opening many about:newtab pages successfully, so RemotePageManager is handling most of them. For some reason it misses some. This happens even with newtab.preload=false (as there's too many browsers needed to wait to use the preloaded one anyway).

I added some dumps to portCreated@RemotePageManager and on "RemotePage:Load" and opened 10 tabs from the browser console:

for (i = 0; i < 10; i++) BrowserOpenTab()

command line showed:

JavaScript error: resource://activity-stream/data/content/activity-stream.bundle.js, line 754: ReferenceError: addMessageListener is not defined
port created 85642:0
port created 85642:1
port created 85633:2
port created 85633:3
JavaScript error: resource://activity-stream/data/content/activity-stream.bundle.js, line 754: ReferenceError: addMessageListener is not defined
port loaded 85642:0
port loaded 85642:1
port loaded 85633:2
JavaScript error: resource://activity-stream/data/content/activity-stream.bundle.js, line 754: ReferenceError: addMessageListener is not defined
JavaScript error: resource://activity-stream/data/content/activity-stream.bundle.js, line 754: ReferenceError: addMessageListener is not defined
port loaded 85633:3
JavaScript error: resource://activity-stream/data/content/activity-stream.bundle.js, line 754: ReferenceError: addMessageListener is not defined
JavaScript error: resource://activity-stream/data/content/activity-stream.bundle.js, line 754: ReferenceError: addMessageListener is not defined

In this latter set of 10, the resulting tabs shown along with the tab hover title:

1: bad 85640
2: bad 85641
3: good 85642
4: good 85633
5: bad 85640
6: bad 85641
7: good 85642
8: good 85633
9: bad 85640
10: bad 85641

Mossop: any suggestions on how to debug? Or maybe we can just work around by detecting missing addMessageListener and reloading the page (note: addMessageListener never appears later, so something got lost in creating the port).

Comment 1

[Ed Lee :Mardak]

Mossop: Looks like the underlying issue for RemotePageManager is that the new child requested "RemotePage:InitListener" but the "RemotePage:Register" response wasn't even sent by the time the child needs to check registeredURLs.has("about:newtab").

Here's some logs (I made up random IDs) of slowly opening 5 about:newtabs (1st content process was created earlier):

[2:bc] RemotePageManager.jsm loaded
[2:bc] Services.cpmm.sendAsyncMessage("RemotePage:InitListener");
[0:5d] [2:bc].sendAsyncMessage("RemotePage:Register", { urls: ["about:plugins","about:newtab","about:tabcrashed"] });
[2:bc] registeredURLs.has("about:blank") === false
[2:bc] registeredURLs.add("about:plugins","about:newtab","about:tabcrashed");
[2:bc] registeredURLs.has("about:newtab") === true
[2:0f] RemotePageManager.jsm loaded
[2:0f] Services.cpmm.sendAsyncMessage("RemotePage:InitListener");
[0:5d] [2:0f].sendAsyncMessage("RemotePage:Register", { urls: ["about:plugins","about:newtab","about:tabcrashed"] });
[2:0f] registeredURLs.has("about:blank") === false
[2:0f] registeredURLs.add("about:plugins","about:newtab","about:tabcrashed");
[2:0f] registeredURLs.has("about:newtab") === true
[2:be] RemotePageManager.jsm loaded
[2:be] Services.cpmm.sendAsyncMessage("RemotePage:InitListener");
[0:5d] [2:be].sendAsyncMessage("RemotePage:Register", { urls: ["about:plugins","about:newtab","about:tabcrashed"] });
[2:be] registeredURLs.has("about:blank") === false
[2:be] registeredURLs.add("about:plugins","about:newtab","about:tabcrashed");
[2:be] registeredURLs.has("about:newtab") === true
[2:dc] registeredURLs.has("about:blank") === false
[2:dc] registeredURLs.has("about:newtab") === true
[2:bc] registeredURLs.has("about:blank") === false
[2:bc] registeredURLs.has("about:newtab") === true

And here's what happens when I open 5 tabs very quickly:

[2:6b] RemotePageManager.jsm loaded
[2:6b] Services.cpmm.sendAsyncMessage("RemotePage:InitListener");
[2:6b] registeredURLs.has("about:blank") === false
[2:de] RemotePageManager.jsm loaded
[2:de] Services.cpmm.sendAsyncMessage("RemotePage:InitListener");
[2:6b] registeredURLs.has("about:blank") === false
[2:6b] registeredURLs.has("about:newtab") === false <--- oops
[2:6b] registeredURLs.has("about:newtab") === false <--- oops
[2:de] registeredURLs.has("about:blank") === false
[0:42] [2:6b].sendAsyncMessage("RemotePage:Register", { urls: ["about:plugins","about:newtab","about:tabcrashed"] }); <--- late
[0:42] [2:de].sendAsyncMessage("RemotePage:Register", { urls: ["about:plugins","about:newtab","about:tabcrashed"] });
[2:ee] RemotePageManager.jsm loaded
[2:ee] Services.cpmm.sendAsyncMessage("RemotePage:InitListener");
[2:de] registeredURLs.add("about:plugins","about:newtab","about:tabcrashed");
[2:de] registeredURLs.has("about:newtab") === true
[2:fe] registeredURLs.has("about:blank") === false
[0:42] [2:ee].sendAsyncMessage("RemotePage:Register", { urls: ["about:plugins","about:newtab","about:tabcrashed"] });
[2:fe] registeredURLs.has("about:newtab") === true
[2:ee] registeredURLs.has("about:blank") === false
[2:6b] registeredURLs.add("about:plugins","about:newtab","about:tabcrashed"); <--- late
[2:ee] registeredURLs.add("about:plugins","about:newtab","about:tabcrashed");
[2:ee] registeredURLs.has("about:newtab") === true

Once the 4 content processes has registered correctly, looks like all future about:newtabs are managed as expected.

Comment 2

[Ed Lee :Mardak]

k88hudson, if we do go with just reloading the page when addMessageListener is missing, it looks like it doesn't break any tests:

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

Here's the count of reloads / failed to register about:newtab in new content proccess for browser-chrome tests:

browser_633221.js
Lin64 opt:  3 reloads https://public-artifacts.taskcluster.net/DTcYhCgZROyN_ARCGLzVEw/0/public/logs/live_backing.log

browser_all_files_referenced.js
Lin64 opt: 30 reloads https://public-artifacts.taskcluster.net/W7HEc-ozRO-VjUjP8tT4Dw/0/public/logs/live_backing.log
OSX10 opt: 56 reloads https://public-artifacts.taskcluster.net/ehSIk-uOR3qvC0vSPiJJqA/0/public/logs/live_backing.log
Win 7 opt: 12 reloads https://public-artifacts.taskcluster.net/BVMiKnoDQgWsckcF4VTKuA/0/public/logs/live_backing.log
Win 7 deb: 12 reloads https://public-artifacts.taskcluster.net/cUJ7QXlnRQySVAcPtVdJSw/0/public/logs/live_backing.log

browser_shutdown_acc_reference.js
Lin64 opt:  2 reloads https://public-artifacts.taskcluster.net/UWfFNNxqTRafPrRft_UxvA/0/public/logs/live_backing.log
Lin64 deb:  9 reloads https://public-artifacts.taskcluster.net/YqYNu3PtRSeA8QN0gmtJPA/0/public/logs/live_backing.log
OSX10 opt:  1 reload  https://public-artifacts.taskcluster.net/D1Tumo5FTzmIGZSNBWHp7g/0/public/logs/live_backing.log
OSX10 deb: 15 reloads https://public-artifacts.taskcluster.net/RvDKJpwVQdySiqHLDQuGiA/0/public/logs/live_backing.log
Win 7 opt:  3 reloads https://public-artifacts.taskcluster.net/XRxJzfMjR3WysI3-hjL4wg/0/public/logs/live_backing.log
Win 7 deb:  3 reloads https://public-artifacts.taskcluster.net/TO34bedCQ3ehSRnrrCYyeg/0/public/logs/live_backing.log

Comment 3

[Ed Lee :Mardak]

I haven't been able to reproduce bug 1385718 or bug 1387852 where sessionstore results in a broken about:newtab, but potentially this bug is the underlying issue for both (same?) issues.

mikedeboer, maybe you know who can help debug this intersection of RemotePageManager and sessionstore? (sorry I'm running off on PTO)

In comment 1, I noticed that a just-created child process doesn't get the RemotePage urls to register until it has already observed document-created when many xul:browsers are loading. Seems like when there's a lot of new xul:browsers, some messages get priority or at least push down the priority of delivering `Services.cpmm.sendAsyncMessage("RemotePage:InitListener")`

In bug 1387852 comment 27, I noticed that as sessionstore adds tabs, a preloaded browser is created for about:newtab. This potentially simulates the "create many xul:browsers" situation of `for (i = 0; i < 10; i++) BrowserOpenTab()`


gabor, I did try turning on dom.ipc.processPrelaunch.enabled and it does seem to help, but here it's trying to create 3 additional content processes instead of using just the 1 prelaunched. From my tests of doing 10x BrowserOpenTab, here's the count of "addMessageListener is not defined" exceptions across 10 runs:

prelaunch false: 6, 5, 7, 6, 5, 6, 5, 5, 6, 6
prelaunch  true: 3, 3, 3, 3, 4, 3, 4, 3, 4, 4

And as a sanity check, when I drop ipc.processCount to 2 and prelaunch = true, I get no errors even when opening 100 tabs at a time. And with processCount = 2 and prelaunch = false, opening 100 tabs results in 50 of them hitting the exception.

Comment 4

[Dave Townsend [:mossop]]

So we only use the InitListener message to pass the registered urls down to a newly created content process. This was before we had intitialProcessData available. We could just use that now which would guarantee we have the data in advance of when we need it.

Comment 5

[Mike de Boer [:mikedeboer]]

(In reply to Ed Lee :Mardak (PTO Aug 12 - Aug 20) from comment #3)
> In bug 1387852 comment 27, I noticed that as sessionstore adds tabs, a
> preloaded browser is created for about:newtab. This potentially simulates
> the "create many xul:browsers" situation of `for (i = 0; i < 10; i++)
> BrowserOpenTab()`

Well, there's no sessionstore-specific code that creates an about:newtab browser during startup. In fact I don't think that sessionstore does anything meaningful during startup except for init, which loads the sessionstore file and checks whether the browser crashed before and should restore right away or show the about:sessionrestore page.
If a browser element is created, it'd be done by the tabbrowser init code, which runs after sessionstore init.

I think Dave's suggestion of using `initialProcessData` in RemotePageManager and other parts of Activity Stream when applicable is the most promising so far. Make sure your bootstrapping logic does not depend on any async (init) flow of underlying components and modules that you may use.

Comment 6

[Ed Lee :Mardak]

Attachment: Bug 1389701 - Newly loaded child RemotePageManager can register pages too late to properly manage created documents.

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

Comment 7

[Dave Townsend [:mossop]]

Comment on attachment 8898366 [details]
Bug 1389701 - Newly loaded child RemotePageManager can register pages too late to properly manage created documents.

https://reviewboard.mozilla.org/r/169730/#review174984

Perfect!

Comment 8

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/e81a6f33863a
Newly loaded child RemotePageManager can register pages too late to properly manage created documents. r=mossop

Comment 9

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

https://hg.mozilla.org/mozilla-central/rev/e81a6f33863a