1628416 - Failure initializing search engines after polling Production Preview (Remote Settings poll preview update)

Status: RESOLVED FIXED

(Firefox :: Remote Settings Client, defect, P3)

Description

[Adrian Florinescu [:aflorinescu]]

[Environment:]

77.0a1 20200408033650 / Windows 10

[Steps:]

1. Install Nightly.
2. Install the RS addon
3. Fire up the RS addon.
4. From the addon set the Environment to Prod(Preview).
5. Clear ALL local data and Clear poll data.
6. Poll server afterwhich close and reopen Nightly.

[Actual Result:]

No engines are initialized.
see debug log

[Expected Result:]

The engines should be initialized.

[Note:]

1. The issue doesn't seem reproducible with Production as Environment.
2. Even though this issue might be related to the RS addon and clearing all the local and poll data, it is concerning that we can reach a state of no engines availble.
3. Later edit Seems my Ubuntu 18.04 machine doesn't exibit this init issue with the STR listed above. I'm gonna give it a push tomorrow with mac aswell.

Comment 1

[Mark Banner (:standard8)]

As far as I can tell, this is an issue in Remote Settings somewhere. The STR only appear to happen on a fresh profile, when it does happen, a subsequent restart works fine. I think we might have seen a potential similar instance in the wild with bug 1632914 - though I've not enough data to be sure.

Here's the STR with annotated comments:

1. Install Nightly - needs a fresh profile.
2. Install the RS addon
3. Fire up the RS addon.
4. From the addon set the Environment to Prod(Preview).

I also added search & remote settings logging, and added some logging into the SearchEngineSelector._getConfiguration() handler.

5. Clear ALL local data and Clear poll data.
6. Poll server - I wait for the page to finish working at this stage - after which close and reopen Nightly.

At this stage, I see:

_init start
services.settings: Instantiated new client main-preview/search-config
services.settings: Instantiated new client main-preview/hijack-blocklists remote-settings.js:112
browser.startup.average_time - Truncating float/double number.
services.settings: main-preview/hijack-blocklists verify signature of local data on read RemoteSettingsClient.jsm:330
services.settings: Required metadata for main-preview/hijack-blocklists, fetching from server.
SearchService.init: false 2
services.settings: Instantiated new client main-preview/fxmonitor-breaches remote-settings.js:112
Unknown category for SetEventRecordingEnabled: fxmonitor
_loadEngines: start
_findEngineSelectorEngines: init
Object { result: [] } SearchEngineSelector.jsm:134:15
Object { config: [] } SearchEngineSelector.jsm:179:13
SearchEngineSelector fetchEngineConfiguration GB:en-US:default::null:firefox:77.0a1

SearchEngineSelector fetchEngineConfiguration: 

_init: failure initializing search: TypeError: can't access property "webExtension", defaultEngine is undefined

The interesting bit is the result and config objects - the get() call to the RemoteSettingsClient has succeeded (I had logging in for exceptions as well), but returned no records.

Whilst I've been writing this comment, remote settings has done a poll and noted:

services.settings: Fetch changes from server (expected=1588177845540, since=undefined) RemoteSettingsClient.jsm:771
services.settings: main-preview/search-config local timestamp: 0, remote: 1588177845540 RemoteSettingsClient.jsm:789
services.settings: main-preview/search-config 0 to delete, 79 to insert RemoteSettingsClient.jsm:799
services.settings: main-preview/search-config 79 created. 0 updated. 0 deleted. RemoteSettingsClient.jsm:882
services.settings: main-preview/search-config sync status is success RemoteSettingsClient.jsm:630

Seeing as the manual poll server was done before the restart, surely the records should have been saved to the database?

Comment 2

[Mathieu Leplatre [:leplatrem]]

I'm trying to reproduce, and fail... (on changeset: 602852:8e4a846c1c5b, Linux)

This is what I do:

1. Create an empty profile (thanks Mark)

$ ./obj-x86_64-pc-linux-gnu/dist/bin/firefox -createProfile rs-searchconfig

2. Set relevant preferences in user.js

user_pref("services.settings.load_dump", false);
user_pref("services.settings.loglevel", "all");
user_pref("services.settings.server", "https://settings.stage.mozaws.net/v1");
user_pref("security.content.signature.root_hash", "DB:74:CE:58:E4:F9:D0:9E:E0:42:36:BE:6C:C5:C4:F6:6A:E7:74:7D:C0:21:42:7A:03:BC:2F:57:0C:8B:9B:90");
user_pref("services.settings.default_bucket", "main-preview");

3. I quickly added an additional debug message in RemoteSettingsClient.jsm to get the number of records returned by .get(). And then run:

./mach build faster
./mach run -P rs-searchconfig -purgecaches
 0:00.27 /home/mathieu/Code/Mozilla/firefox/artifacts/obj-x86_64-pc-linux-gnu/dist/bin/firefox -P rs-searchconfig -purgecaches -no-remote

console.debug: services.settings: 
  Instantiated new client main-preview/search-config
console.debug: services.settings: 
  main-preview/search-config Local DB is empty, pull data from server
[...]
console.debug: services.settings: 
  main-preview/search-config Fetch changes from server (expected=1587992386690, since=undefined)
[...]
console.debug: services.settings: 
  main-preview/search-config local timestamp: null, remote: 1587992386690
console.debug: services.settings: 
  main-preview/search-config 0 to delete, 5 to insert
[...]
console.debug: services.settings: 
  main-preview/search-config 5 created. 0 updated. 0 deleted.
console.debug: services.settings: 
  main-preview/search-config sync status is success
console.debug: services.settings: 
  main-preview/search-config 5 records before filtering.
console.debug: services.settings: 
  main-preview/search-config 5 records after filtering.

I can see that the 5 records are pulled and returned. Plus the timestamp matches STAGE preview collection.

Comment 3

[Mark Banner (:standard8)]

Note that we were only changing from prod to prod-preview. We were also doing this with the extension, clearing the databases down, re-poll, and then a restart.

The STR need to be exact otherwise it doesn't seem to reproduce.

Comment 4

[Mathieu Leplatre [:leplatrem]]

Ok, I can reproduce.

The problem comes from the addon and the environment switching.
After switching buckets (from main to main-preview), the clearing of local data puts 0 in the timestamps table (instead of null or removing entries).

In .get(), in order to check if we have local data for a certain collection, we look at the timestamps. And in that case, since we have 0 (and not null), we consider that we have local data and thus we don't pull anything from the server.

As a workaround, you can avoid the environment switching from the addon. Create an empty profile with user_pref("services.settings.default_bucket", "main-preview"); and you'll have a fresh start with preview data.

I'll keep you posted once I find a fix

Comment 5

[Mark Banner (:standard8)]

Thanks for the comment. I'm going to remove this from blocking search modernisation, as this looks to be a result from the add-on and switching, rather than something we'd be able to hit normally.

Comment 6

[BugBot [:suhaib / :marco/ :calixte]]

The priority flag is not set for this bug.
:leplatrem, could you have a look please?

For more information, please visit auto_nag documentation.

Comment 7

[BugBot [:suhaib / :marco/ :calixte]]

In the process of migrating remaining bugs to the new severity system, the severity for this bug cannot be automatically determined. Please retriage this bug using the new severity system.

Comment 8

[BugBot [:suhaib / :marco/ :calixte]]

The severity field is not set for this bug.
:leplatrem, could you have a look please?

For more information, please visit auto_nag documentation.

Comment 9

[Mathieu Leplatre [:leplatrem]]

Switching environments has been remodeled in Bug 1702759, I will mark this bug as invalid since I believe it was fixed in mean time.