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

RESOLVED FIXED in Firefox 57

Status

()

Firefox
Activity Streams: Newtab
RESOLVED FIXED
3 months ago
3 months ago

People

(Reporter: Mardak, Assigned: Mardak)

Tracking

Trunk
Firefox 57
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox57 fixed)

Details

MozReview Requests

()

Submitter Diff Changes Open Issues Last Updated
Loading...
Error loading review requests:

Attachments

(1 attachment)

(Assignee)

Description

3 months ago
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).
Flags: needinfo?(dtownsend)
(Assignee)

Comment 1

3 months ago
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.
Summary: Sometimes RemotePageManager is too slow / never gets the port → Newly loaded child RemotePageManager can register pages too late to properly manage created documents
(Assignee)

Comment 2

3 months ago
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
(Assignee)

Comment 3

3 months ago
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.
Blocks: 1385718, 1387852
Flags: needinfo?(mdeboer)
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.
Flags: needinfo?(dtownsend)
(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.
Flags: needinfo?(mdeboer)
Comment hidden (mozreview-request)

Comment 7

3 months ago
mozreview-review
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!
Attachment #8898366 - Flags: review?(dtownsend) → review+

Comment 8

3 months ago
Pushed by edilee@gmail.com:
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

3 months ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/e81a6f33863a
Status: NEW → RESOLVED
Last Resolved: 3 months ago
status-firefox57: affected → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 57
(Assignee)

Updated

3 months ago
Blocks: 1386322
Assignee: nobody → edilee
Depends on: 1393422
You need to log in before you can comment on or make changes to this bug.