1399312 - Intermittent test_safe_browsing_initial_download.py TestSafeBrowsingInitialDownload.test_safe_browsing_initial_download | AssertionError: 'goog-phish-shavar.sbstore' not found in ['allow-flashallow-digest256.pset', 'allow-flashallow-digest256.sbstore', 'b

Status: RESOLVED FIXED

(Toolkit :: Safe Browsing, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: rvandermeulen [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=130502571&repo=mozilla-beta

https://queue.taskcluster.net/v1/task/PaGhfrIPTX6aZNOTaVTGDw/runs/0/artifacts/public/logs/live_backing.log

Comment 1

[Henrik Skupin [:whimboo][⌚️UTC+2] (away 10/03 - 10/13)]

I cannot find any google related lists here:

18:48:28     INFO - TEST-UNEXPECTED-FAIL | test_safe_browsing_initial_download.py TestSafeBrowsingInitialDownload.test_safe_browsing_initial_download | AssertionError: 'goog-phish-shavar.sbstore' not found in ['allow-flashallow-digest256.pset', 'allow-flashallow-digest256.sbstore', 'base-track-digest256.pset', 'base-track-digest256.sbstore', 'block-flash-digest256.pset', 'block-flash-digest256.sbstore', 'block-flashsubdoc-digest256.pset', 'block-flashsubdoc-digest256.sbstore', 'except-flash-digest256.pset', 'except-flash-digest256.sbstore', 'except-flashallow-digest256.pset', 'except-flashallow-digest256.sbstore', 'except-flashinfobar-digest256.pset', 'except-flashinfobar-digest256.sbstore', 'except-flashsubdoc-digest256.pset', 'except-flashsubdoc-digest256.sbstore', 'google4', 'mozplugin-block-digest256.pset', 'mozplugin-block-digest256.sbstore', 'mozstd-trackwhite-digest256.pset', 'mozstd-trackwhite-digest256.sbstore', 'test-block-simple.pset', 'test-block-simple.sbstore', 'test-malware-simple.pset', 'test-malware-simple.sbstore', 'test-phish-simple.pset', 'test-phish-simple.sbstore', 'test-track-simple.pset', 'test-track-simple.sbstore', 'test-trackwhite-simple.pset', 'test-trackwhite-simple.sbstore', 'test-unwanted-simple.pset', 'test-unwanted-simple.sbstore']
18:48:28     INFO - Traceback (most recent call last):
18:48:28     INFO -   File "/Users/cltbld/tasks/task_1505267073/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 156, in run
18:48:28     INFO -     testMethod()
18:48:28     INFO -   File "/Users/cltbld/tasks/task_1505267073/build/tests/firefox-ui/tests/functional/security/test_safe_browsing_initial_download.py", line 106, in test_safe_browsing_initial_download
18:48:28     INFO -     self.assertIn(f, files_on_disk_toplevel)
18:48:28     INFO - TEST-INFO took 173763ms

Comment 2

[François Marier [:francois]]

Thomas, would you have time to take a look at this test?

Comment 3

[Intermittent Failures Robot]

32 failures in 1032 pushes (0.031 failures/push) were associated with this bug in the last 7 days.   

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **  

Repository breakdown:
* mozilla-beta: 32

Platform breakdown:
* linux64-nightly: 10
* windows7-32-nightly: 4
* windows10-64-nightly: 4
* macosx64-nightly: 4
* linux32-nightly: 4
* macosx64-devedition: 3
* windows7-32-devedition: 1
* linux64-devedition: 1
* linux32-devedition: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1399312&startday=2017-09-11&endday=2017-09-17&tree=all

Comment 4

[Thomas Nguyen (:tnguyen)]

02:54:19     INFO -  1505616859642	Marionette	TRACE	22 -> [0,64,"executeScript",{"scriptTimeout":null,"newSandbox":true,"args":["urlclassifier.phishTable",false,"nsISupportsString"],"filename":"marionette.py","script":"\n                Components.utils.import(\"resource://gre/modules/Preferences.jsm\");\n\n                let pref = arguments[0];\n                let defaultBranch = arguments[1];\n                let valueType = arguments[2];\n\n                prefs = new Preferences({defaultBranch: defaultBranch});\n                return prefs.get(pref, null, Components.interfaces[valueType]);\n                ","sandbox":"default","line":886}]
02:54:19     INFO -  1505616859643	Marionette	TRACE	22 <- [1,64,null,{"value":"goog-phish-shavar,test-phish-simple"}]
02:54:19     INFO -  1505616859644	Marionette	TRACE	22 -> [0,65,"setContext",{"value":"chrome"}]
02:54:19     INFO -  1505616859645	Marionette	TRACE	22 <- [1,65,null,{}]
02:54:19     INFO -  1505616859645	Marionette	TRACE	22 -> [0,66,"getContext",{}]
02:54:19     INFO -  1505616859646	Marionette	TRACE	22 <- [1,66,null,{"value":"chrome"}]
02:54:19     INFO -  1505616859646	Marionette	TRACE	22 -> [0,67,"setContext",{"value":"chrome"}]
02:54:19     INFO -  1505616859647	Marionette	TRACE	22 <- [1,67,null,{}]
02:54:19     INFO -  1505616859649	Marionette	TRACE	22 -> [0,68,"executeScript",

Henrik, do you know if prefs in firefox.js don't take effect?
https://dxr.mozilla.org/comm-beta/rev/f81f90c4fcb3bef81ca3a06dc79d08ed8dce21d3/mozilla/browser/app/profile/firefox.js#1715

Comment 5

[Henrik Skupin [:whimboo][⌚️UTC+2] (away 10/03 - 10/13)]

Not sure from which build that is but if I chose this one here I see:

https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-beta&job_id=131559301&lineNumber=19572

02:54:08     INFO - mozinfo is: {u'bin_suffix': u'.exe', u'pgo': True, u'sync': True, u'buildapp': u'browser', u'crashreporter': True, u'addon_signing': True, u'require_signing': True, u'release_or_beta': True, u'appname': u'firefox', u'stylo': False, u'mozconfig': u'z:/build/build/src/.mozconfig', u'topsrcdir': u'z:/build/build/src', u'telemetry': False, 'os_version': StringVersion ('10.0'), 'version': '10.0.15063', u'datareporting': True, u'buildtype_guess': u'pgo', 'bits': 64, 'has_sandbox': True, 'service_pack': '', u'artifact': False, u'toolkit': u'windows', u'healthreport': True, u'updater': True, u'asan': False, u'platform_guess': u'win64', u'ccov': False, u'ubsan': False, u'tests_enabled': True, u'official': True, u'tsan': False, u'nightly_build': False, u'debug': False, u'no_legacy_extensions': False, 'os': u'win', 'processor': u'x86_64'}

There is "official: True" for a Nightly build. Is that what we expect? I doubt so. Only beta releases should have an official branding or?

Comment 6

[Thomas Nguyen (:tnguyen)]

(In reply to Henrik Skupin (:whimboo) from comment #5)
> Not sure from which build that is but if I chose this one here I see:
> 
> https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-
> beta&job_id=131559301&lineNumber=19572
> 

Suspicious log in the test
02:54:19     INFO -  1505616859642	Marionette	TRACE	22 -> [0,64,"executeScript",{"scriptTimeout":null,"newSandbox":true,"args":["urlclassifier.phishTable",false,"nsISupportsString"],"filename":"marionette.py","script":"\n                Components.utils.import(\"resource://gre/modules/Preferences.jsm\");\n\n                let pref = arguments[0];\n                let defaultBranch = arguments[1];\n                let valueType = arguments[2];\n\n                prefs = new Preferences({defaultBranch: defaultBranch});\n                return prefs.get(pref, null, Components.interfaces[valueType]);\n                ","sandbox":"default","line":886}]
5481
02:54:19     INFO -  1505616859643	Marionette	TRACE	22 <- [1,64,null,{"value":"goog-phish-shavar,test-phish-simple"}]
5482
02:54:19     INFO -  1505616859644	Marionette	TRACE	22 -> [0,65,"setContext",{"value":"chrome"}]

And, fwiw, most builds on try are official build (running build with MOZ_OFFICAL=1), except linux 64 asan

Comment 7

[Henrik Skupin [:whimboo][⌚️UTC+2] (away 10/03 - 10/13)]

So in that case why is it suspicious? In firefox.js I see:

> #ifdef MOZILLA_OFFICIAL
> pref("urlclassifier.phishTable", "goog-phish-proto,test-phish-simple");
> #else
> pref("urlclassifier.phishTable", "googpub-phish-proto,test-phish-simple");
> #endif

This perfectly matches both values as returned by Marionette.

Comment 8

[Thomas Nguyen (:tnguyen)]

(In reply to Henrik Skupin (:whimboo) from comment #7)
> So in that case why is it suspicious? In firefox.js I see:
> 
> > #ifdef MOZILLA_OFFICIAL
> > pref("urlclassifier.phishTable", "goog-phish-proto,test-phish-simple");
> > #else
> > pref("urlclassifier.phishTable", "googpub-phish-proto,test-phish-simple");
> > #endif
> 
> This perfectly matches both values as returned by Marionette.

No, we expect to get goog-phish-proto, but actually it gets goog-phish-shavar
02:54:19     INFO -  1505616859643	Marionette	TRACE	22 <- [1,64,null,{"value":"goog-phish-shavar,test-phish-simple"}]

goog-phish-shavar is set in all.js
#ifdef MOZILLA_OFFICIAL
// In the official build, we are allowed to use google's private
// phishing list "goog-phish-shavar". See Bug 1288840.
pref("urlclassifier.phishTable", "goog-phish-shavar,test-phish-simple");
#else
pref("urlclassifier.phishTable", "googpub-phish-shavar,test-phish-simple");
#endif

So, the value in firefox.js does not take effect (we expect urlclassifier.phishTable firefox.js will override urlclassifier.phishTable in all.js)

Comment 9

[Henrik Skupin [:whimboo][⌚️UTC+2] (away 10/03 - 10/13)]

Oh my bad, sorry. So is that a permanent failure or an intermittent? It would be really suspicious if it's the latter. Marionette only uses `Services.prefs` to retrieve the preferences. Are we sure that v4 is enabled for those builds? If not, we would fallback to the values from all.js, right?

Comment 10

[Thomas Nguyen (:tnguyen)]

That is intermittent. And v4 is enabled in the build
https://hg.mozilla.org/releases/mozilla-beta/file/27102a84d91e/browser/app/profile/firefox.js

The interesting point is marionnete client returns unexpected value in all.js (suspicious log in comment 6)
http://searchfox.org/mozilla-central/rev/05c4c3bc0cfb9b0fc66bdfc8c47cac674e45f151/testing/marionette/client/marionette_driver/marionette.py#880

But later in the test, Service.prefs.getCharPref("urlclassifier.phishTable") return correct goog-phish-proto

02:54:21     INFO -  listmanager: 02:54:21 GMT+0000 (Coordinated Universal Time): Initializing list manager
02:54:21     INFO -  listmanager: 02:54:21 GMT+0000 (Coordinated Universal Time): registering goog-phish-proto with https://safebrowsing.googleapis.com/v4/threatListUpdates:fetch?$ct=application/x-protobuf&key=[trimmed-google-api-key]&$httpMethod=POST
02:54:21     INFO -  SafeBrowsing: 02:54:21 GMT+0000 (Coordinated Universal Time): No provider info found for test-phish-simple

Comment 11

[Henrik Skupin [:whimboo][⌚️UTC+2] (away 10/03 - 10/13)]

Can you reproduce it locally? If yes, how long does it take until the preference gets its correct value? Also what happens when you change the call to `get_pref()` and add ´default_branch=True`?.

Comment 12

[Ryan VanderMeulen [:RyanVM]]

(In reply to Henrik Skupin (:whimboo) from comment #5)
> There is "official: True" for a Nightly build. Is that what we expect? I
> doubt so. Only beta releases should have an official branding or?

It's absolutely what you should expect. Release promotion works with regular CI builds.

Comment 13

[François Marier [:francois]]

(In reply to Thomas Nguyen[:tnguyen] ni plz from comment #8)
> No, we expect to get goog-phish-proto, but actually it gets goog-phish-shavar
> 02:54:19     INFO -  1505616859643	Marionette	TRACE	22 <-
> [1,64,null,{"value":"goog-phish-shavar,test-phish-simple"}]

Could that also be the Shield study that rolls Safe Browsing back to V2 shortly after the browser starts?

That would explain why it's intermittent and not completely broken. The Shield study is only sent out to 20% of users (and half of the people in the study are in the control group -- no pref flip).

Comment 14

[Henrik Skupin [:whimboo][⌚️UTC+2] (away 10/03 - 10/13)]

If that would be the case we should clearly uplift the patch on bug 1399628.

Comment 15

[Intermittent Failures Robot]

6 failures in 947 pushes (0.006 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-release: 6

Platform breakdown:
* macosx64-nightly: 3
* linux32-nightly: 3

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1399312&startday=2017-10-09&endday=2017-10-15&tree=all

Comment 16

[Intermittent Failures Robot]

1 failures in 864 pushes (0.001 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-release: 1

Platform breakdown:
* linux32-nightly: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1399312&startday=2017-10-16&endday=2017-10-22&tree=all

Comment 17

[Intermittent Failures Robot]

17 failures in 196 pushes (0.087 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* mozilla-release: 17

Platform breakdown:
* linux32-nightly: 6
* windows10-64-nightly: 4
* linux64-nightly: 4
* windows7-32-nightly: 2
* macosx64-nightly: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1399312&startday=2017-10-26&endday=2017-10-26&tree=all

Comment 18

[Henrik Skupin [:whimboo][⌚️UTC+2] (away 10/03 - 10/13)]

This is a huge amount of failures we see on the mozilla-release branch:

https://treeherder.mozilla.org/#/jobs?repo=mozilla-release&filter-searchStr=Firefox%20UI&filter-tier=1&filter-tier=2&filter-tier=3&fromchange=d57a23a8d5dcddc5d4e390ba73298cd9ae6c3785&selectedJob=134741026

Francois, would you mind checking if that is all related to the shield study? the patch is only available for 57 but not 56. Not sure if we should try to do a one-off uplift, if it is the underlying reason.

Comment 19

[François Marier [:francois]]

The listmanager is initialized with the V2 lists:

13:51:44     INFO -  listmanager: 13:51:44 GMT-0700 (PDT): Initializing list manager
13:51:44     INFO -  listmanager: 13:51:44 GMT-0700 (PDT): registering goog-phish-shavar with https://safebrowsing.google.com/safebrowsing/downloads?client=navclient-auto-ffox&appver=56.0&pver=2.2&key=[trimmed-google-api-key]
13:51:44     INFO -  listmanager: 13:51:44 GMT-0700 (PDT): registering goog-malware-shavar with https://safebrowsing.google.com/safebrowsing/downloads?client=navclient-auto-ffox&appver=56.0&pver=2.2&key=[trimmed-google-api-key]
13:51:44     INFO -  listmanager: 13:51:44 GMT-0700 (PDT): registering goog-unwanted-shavar with https://safebrowsing.google.com/safebrowsing/downloads?client=navclient-auto-ffox&appver=56.0&pver=2.2&key=[trimmed-google-api-key]
13:51:44     INFO -  listmanager: 13:51:44 GMT-0700 (PDT): registering goog-badbinurl-shavar with https://safebrowsing.google.com/safebrowsing/downloads?client=navclient-auto-ffox&appver=56.0&pver=2.2&key=[trimmed-google-api-key]
13:51:44     INFO -  listmanager: 13:51:44 GMT-0700 (PDT): registering goog-downloadwhite-digest256 with https://safebrowsing.google.com/safebrowsing/downloads?client=navclient-auto-ffox&appver=56.0&pver=2.2&key=[trimmed-google-api-key]

and successfully does a list update:

13:51:57     INFO -  listmanager: 13:51:57 GMT-0700 (PDT): update success for goog-phish-shavar,goog-malware-shavar,goog-unwanted-shavar,goog-badbinurl-shavar,goog-downloadwhite-digest256 from https://safebrowsing.google.com/safebrowsing/downloads?client=navclient-auto-ffox&appver=56.0&pver=2.2&key=[trimmed-google-api-key]: 1777
13:51:57     INFO -  listmanager: 13:51:57 GMT-0700 (PDT): Waiting 29.616666666666667min
13:51:57     INFO -  listmanager: 13:51:57 GMT-0700 (PDT): Setting last update of google to 1507063917352

However, when the test looked at the prefs, it was all V4 lists and so that's what it's timing out waiting for:

13:51:42     INFO -  1507063902523	Marionette	TRACE	98 -> [0,52,"executeScript",{"scriptTimeout":null,"newSandbox":true,"args":["urlclassifier.downloadAllowTable",false,"nsISupportsString"],"filename":"marionette.py","script":"\n                Components.utils.import(\"resource://gre/modules/Preferences.jsm\");\n\n                let pref = arguments[0];\n                let defaultBranch = arguments[1];\n                let valueType = arguments[2];\n\n                prefs = new Preferences({defaultBranch: defaultBranch});\n                return prefs.get(pref, null, Components.interfaces[valueType]);\n                ","sandbox":"default","line":886}]
13:51:42     INFO -  1507063902525	Marionette	TRACE	98 <- [1,52,null,{"value":"goog-downloadwhite-proto"}]

The order is odd: first, the test script gets V4 values when reading the prefs, then Safe Browsing reads the same prefs and gets the V2 values:

13:51:44     INFO -  SafeBrowsing: 13:51:44 GMT-0700 (PDT): reading prefs
13:51:44     INFO -  SafeBrowsing: 13:51:44 GMT-0700 (PDT): getLists: urlclassifier.phishTable
13:51:44     INFO -  SafeBrowsing: 13:51:44 GMT-0700 (PDT): getLists: urlclassifier.malwareTable
13:51:44     INFO -  SafeBrowsing: 13:51:44 GMT-0700 (PDT): getLists: urlclassifier.downloadBlockTable
13:51:44     INFO -  SafeBrowsing: 13:51:44 GMT-0700 (PDT): getLists: urlclassifier.downloadAllowTable

But the fact that it changes from V2 to V4 at some point does point towards the Shield study as the root cause since that's what it does.

(In reply to Henrik Skupin (:whimboo) from comment #18)
> Not sure if we should try to do a one-off uplift, if it is the underlying reason.

If we want to eliminate these test failures on release, we should disable Shield in the marionette tests there like we did on 57.

Comment 20

[Intermittent Failures Robot]

25 failures in 912 pushes (0.027 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-release: 25

Platform breakdown:
* linux32-nightly: 7
* linux64-nightly: 6
* windows10-64-nightly: 5
* windows7-32-nightly: 4
* macosx64-nightly: 3

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1399312&startday=2017-10-23&endday=2017-10-29&tree=all

Comment 21

[Henrik Skupin [:whimboo][⌚️UTC+2] (away 10/03 - 10/13)]

Thanks Francois. I will ask Ryan on that other bug, if an uplift would be possible and wanted.

This failure itself is fixed now with my patch on bug 1399628.