Fix Bug 1450875 - Wait for Sections to be added before broadcasting content

[piatra]

It looks like the SectionsManager does not initialise/add the sections until PREFS_INITIAL_VALUES because prefs are required for sections. PREFS_INITIAL_VALUES is triggered after INIT, but INIT also triggers Topsites to update and afterwards the HighlightsFeed. If the SectionsManager hasn't finished before the HighlightsFeed.fetchHighlights call, then we run into this issue.

I wasn't able to reproduce, what I did was add an await call for a promise resolved in a setTimeout in addBuiltInSection.

I propose that we just return early if we don't have the sections available yet because when they finally become available the feed will trigger the postInit fetch

This is just a WIP to open the discussion.

@Mardak thoughts?

[Mardak]

The line that is failing was added in #4022 more than a month ago:

activity-stream/system-addon/lib/HighlightsFeed.jsm

Line 163 in e1b7660

const {initialized} = this.store.getState().Sections.find(section => section.id === SECTION_ID);

Before the change #3695 was doing a different type of access but probably would have run into an exception too:

activity-stream/system-addon/lib/HighlightsFeed.jsm

Lines 116 to 117 in 8850b8b

	const sectionIndex = SectionsManager.sections.get(SECTION_ID).order;
	const {initialized} = this.store.getState().Sections[sectionIndex];

So something other than those changes must have caused this exception to start appearing. The earliest failures seem to be from 8 days ago which seems to suggest a change from bug 1449792 export 837cea5...6170061

My guess is @sarracini's changes for #4059 where in particular, TopSitesFeed now refreshes on places links changed instead of deleted:
e1b7660#diff-3c9ab687b10408604222f1cb5b298d0e

Perhaps it's triggering more refreshes than desired now… ?

Also, looking at the taskcluster logs, it doesn't seem to necessarily fail on startup as other tests seem to have passed okay. Perhaps the added debouncing logic is causing a continuation after things have uninitialized somehow?

This looks like a regression, so we need to figure out how to reproduce the issue so we can track down what change is causing the problem and then we can figure out how to fix the cause or avoid it.

[Mardak]

I happened to trigger a try with a m-c merge from today, but I wasn't able to reproduce this with logging after 800 retries:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=c043c3c931bf7a1088051485cd721fe66f2fe7dd

Although looking at the logs when printing:

o.push(`${action.type} ${(d => d.id || d.name || Object.keys(d))(action.data || {})}\n`);
if (action.type === "SECTION_UPDATE") o.push(Error().stack.split("\n").slice(6, 10));

INIT version
PREFS_INITIAL_VALUES default.sites,feeds.section.topstories.options,showSponsored,filterAdult,migrationExpired,migrationLastShownDate,migrationRemainingDays,prerender,showSearch,disableSnippets,topSitesRows,telemetry,telemetry.ut.events,telemetry.ping.endpoint,section.highlights.includePocket,section.topstories.showDisclaimer,tippyTop.service.endpoint,enableWideLayout,sectionOrder,messageCenterExperimentEnabled,feeds.aboutpreferences,feeds.migration,feeds.newtabinit,feeds.places,feeds.prefs,feeds.theme,feeds.sections,feeds.section.highlights,feeds.section.topstories,feeds.snippets,feeds.systemtick,feeds.telemetry,feeds.favicon,feeds.topsites,feeds.messagecenterfeed,isPrivateBrowsingEnabled
THEME_UPDATE className
SECTION_REGISTER topstories
SECTION_REGISTER highlights
SECTION_UPDATE highlights postInit@resource://activity-stream/lib/HighlightsFeed.jsm:54:5,…,init@resource://activity-stream/lib/SectionsManager.jsm:104:5
TOP_SITES_UPDATED links,pref
SECTION_UPDATE highlights async*onAction@resource://activity-stream/lib/HighlightsFeed.jsm:242:9,…,refresh@resource://activity-stream/lib/TopSitesFeed.jsm:180:7
SECTION_UPDATE highlights async*observe@resource://activity-stream/lib/HighlightsFeed.jsm:74:7,notifyObservers@resource://gre/modules/BookmarkHTMLUtils.jsm:116:3,importFromURL@resource://gre/modules/BookmarkHTMLUtils.jsm:149:7,async*BG__initPlaces/<@jar:file:///builds/worker/workspace/build/application/firefox/browser/omni.ja!/components/nsBrowserGlue.js:1672:21
SET_PREF migrationRemainingDays
PREF_CHANGED migrationRemainingDays
SET_PREF migrationLastShownDate
PREF_CHANGED migrationLastShownDate
NEW_TAB_INIT addMessageListener,removeMessageListener,sendAsyncMessage,destroy,portID,browser,url,loaded
PLACES_HISTORY_CLEARED
SECTION_UPDATE highlights async*onAction@resource://activity-stream/lib/HighlightsFeed.jsm:247:9,…,customDispatch@resource://activity-stream/lib/PlacesFeed.jsm:209:7
TOP_SITES_UPDATED links,pref
SECTION_UPDATE highlights async*onAction@resource://activity-stream/lib/HighlightsFeed.jsm:242:9,…,refresh@resource://activity-stream/lib/TopSitesFeed.jsm:180:7
NEW_TAB_STATE_REQUEST
NEW_TAB_INITIAL_STATE TopSites,App,Snippets,Prefs,Dialog,Sections,Theme
NEW_TAB_LOAD
NEW_TAB_REHYDRATED
SAVE_SESSION_PERF_DATA topsites_icon_stats,topsites_pinned
PAGE_PRERENDERED
SAVE_SESSION_PERF_DATA topsites_data_late_by_ms
SAVE_SESSION_PERF_DATA highlights_data_late_by_ms
SAVE_SESSION_PERF_DATA topsites_icon_stats,topsites_pinned
PLACES_HISTORY_CLEARED
SECTION_UPDATE highlights async*onAction@resource://activity-stream/lib/HighlightsFeed.jsm:247:9,…,customDispatch@resource://activity-stream/lib/PlacesFeed.jsm:209:7
TOP_SITES_UPDATED links,pref
SECTION_UPDATE highlights async*onAction@resource://activity-stream/lib/HighlightsFeed.jsm:242:9,…,refresh@resource://activity-stream/lib/TopSitesFeed.jsm:180:7
SAVE_SESSION_PERF_DATA topsites_icon_stats,topsites_pinned
SAVE_SESSION_PERF_DATA topsites_first_painted_ts
PLACES_HISTORY_CLEARED
SECTION_UPDATE highlights async*onAction@resource://activity-stream/lib/HighlightsFeed.jsm:247:9,…,customDispatch@resource://activity-stream/lib/PlacesFeed.jsm:209:7
TOP_SITES_UPDATED links,pref
SECTION_UPDATE highlights async*onAction@resource://activity-stream/lib/HighlightsFeed.jsm:242:9,…,refresh@resource://activity-stream/lib/TopSitesFeed.jsm:180:7
SAVE_SESSION_PERF_DATA topsites_icon_stats,topsites_pinned
NEW_TAB_UNLOAD
UNINIT

Where the SECTION_UPDATES are triggered by:

1. postInit
2. TOP_SITES_UPDATED
3. bookmarks-restore-success observer https://searchfox.org/mozilla-central/rev/a30a60eadcff99d2a043241955d215dbeccad876/browser/components/nsBrowserGlue.js#1672
4. PLACES_HISTORY_CLEARED
5. TOP_SITES_UPDATED
6. PLACES_HISTORY_CLEARED
7. TOP_SITES_UPDATED
8. PLACES_HISTORY_CLEARED
9. TOP_SITES_UPDATED

The first 2 seem to be normal startup stuff. #3 might be test runner / new profile behavior? And the rest I'm guessing are test specific (although it's somewhat wasteful that Highlights refreshes on CLEARED only to refresh immediately after when top sites also decides to refresh on CLEARED).

I believe we're assuming the problem is that SECTION_REGISTER highlights gets delayed until after TOP_SITES_UPDATED.

Looking more closely at how that could happen, I think it's #4058 that made SectionsManager's init async and not @sarracini's #4059 as the regressing change from the range 837cea5...6170061.

addBuiltInSection was made async to wait for indexeddb, whereas before this change, sections would get added and registered synchronously with SectionsManager initializing.

activity-stream/system-addon/lib/SectionsManager.jsm

Lines 126 to 138 in 2e41605

	async addBuiltInSection(feedPrefName, optionsPrefValue = "{}") {
	let options;
	try {
	options = JSON.parse(optionsPrefValue);
	} catch (e) {
	options = {};
	Cu.reportError(`Problem parsing options pref for ${feedPrefName}`);
	}
	const storedPrefs = await this._storage.get(feedPrefName) || {};
	const defaultSection = BUILT_IN_SECTIONS[feedPrefName](options);
	const section = Object.assign({}, defaultSection, {pref: Object.assign({}, defaultSection.pref, getDefaultOptions(storedPrefs))});
	section.pref.feed = feedPrefName;
	this.addSection(section.id, Object.assign(section, {options}));

[piatra]

I could move all indexedDB access to PrefsFeed and only make it accessible thorough the Store for all the consumers. That way I could revert the async changes but I don't think that will fix it, it can still delay PREFS_INITIAL_VALUES to after TOP_SITES_UPDATED and the issue reproduces by different code path.
I think the solution should break this dependency.
Maybe as a patch to this: SectionsManager.init can iterate BUILT_IN_SECTIONS and populate the main reducer with an uninitialized version of the sections (before any async call). We do it for TopSites by having an INITIAL_STATE in the reducer.

[piatra]

Interesting. Was looking at bug 1454110 and locally it triggers the exception in this bug every time.
Update: but does not happen if I check out either #4058 or #4059. Will bisect.

Seems random but locally the failure reproduces every time.

ee4767547d53c06dfc9dc238f2c44164fe5e9d8e is the first bad commit
commit ee4767547d53c06dfc9dc238f2c44164fe5e9d8e
Author: Ricky Rosario <rickyrosario@gmail.com>
Date:   Mon Apr 16 19:33:38 2018 -0400

    Fix Bug 1454501 - apply dark theme only to builtin Dark theme

:040000 040000 64d059e502c76d1ce8e62128cb3581befc6d1a95 2887f6be05abd0d3b949f667aae01d9d7fdede0c M      system-addon

Actually this was already caught by pine. https://treeherder.mozilla.org/#/jobs?repo=pine&revision=f94e1f89458832840e6fe71d0ff625ec228eb895&selectedJob=174021107 Everything is orange.

[Mardak]

Add a comment and rebase. I think this should be fine. The failure situation is top sites updates before highlights is registered. Highlights wants top sites for deduping. If Highlights is slow, it'll return early with this change, and when it does register and refresh via postInit, it'll have top sites to dedupe against, and there's no user facing change.

[Mardak]

Oh, and to be clear, I don't think we need to change the timing / chaining issues related to init / prefs / registering / top sites now with this fix. We'll probably want a test to help ensure highlightsfeed doesn't break if its postInit happens after top sites.

[as-pine-proxy]

Treeherder: 2137284ee1d36ab8747b649e6efdeec87b6655dd