1570984 - TEST-UNEXPECTED-FAIL | browser/base/content/test/trackingUI/browser_trackingUI_socialtracking.js | Test timed out when Gecko 70 merges to Beta on 2019-08-26

Status: VERIFIED FIXED

(Firefox :: Protections UI, defect, P1)

Description

[Arthur Iakab [arthur_iakab]]

[Tracking Requested - why for this release]:
Central as Beta: https://treeherder.mozilla.org/#/jobs?repo=try&resultStatus=testfailed%2Cbusted%2Cexception%2Cretry%2Cusercancel%2Crunnable&revision=c40afe4c82cf9b5198619b2f872e4874492ad4f4

Failure log : https://treeherder.mozilla.org/logviewer.html#?job_id=259576987&repo=try

Gary can you please take a look?

Comment 1

[Gary Chen [:xeonchen]]

(In reply to Arthur Iakab [arthur_iakab] from comment #0)

Gary can you please take a look?

That's what I was worried about because it runs a lot of tests in one single test file, but it showed green on try, so...
I can separate tests into different files, or simply request longer timeout.

Comment 2

[Gary Chen [:xeonchen]]

Attachment: Bug 1570984 - separate large tests;

Comment 3

[Bogdan Tara[:bogdan_tara | bogdant]]

Sadly, i still see this on the late beta simulation:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=259766212&repo=try&lineNumber=2383

[task 2019-08-03T12:32:01.778Z] 12:32:01 INFO - TEST-START | browser/base/content/test/trackingUI/browser_trackingUI_socialtracking.js
[task 2019-08-03T12:35:01.882Z] 12:35:01 INFO - TEST-INFO | started process screentopng
[task 2019-08-03T12:35:02.433Z] 12:35:02 INFO - TEST-INFO | screentopng: exit 0
[task 2019-08-03T12:35:02.433Z] 12:35:02 INFO - Buffered messages logged at 12:32:01
[task 2019-08-03T12:35:02.433Z] 12:35:02 INFO - Entering test bound setup
[task 2019-08-03T12:35:02.435Z] 12:35:02 INFO - Leaving test bound setup
[task 2019-08-03T12:35:02.435Z] 12:35:02 INFO - Entering test bound testIdentityUI
[task 2019-08-03T12:35:02.436Z] 12:35:02 INFO - Buffered messages logged at 12:32:02
[task 2019-08-03T12:35:02.439Z] 12:35:02 INFO - Received onContentBlockingEvent event 1 of 1
[task 2019-08-03T12:35:02.440Z] 12:35:02 INFO - TEST-PASS | browser/base/content/test/trackingUI/browser_trackingUI_socialtracking.js | socialtrackings are not detected -
[task 2019-08-03T12:35:02.441Z] 12:35:02 INFO - TEST-PASS | browser/base/content/test/trackingUI/browser_trackingUI_socialtracking.js | icon box is visible regardless the exception -
[task 2019-08-03T12:35:02.442Z] 12:35:02 INFO - Received onContentBlockingEvent event 1 of 1
[task 2019-08-03T12:35:02.443Z] 12:35:02 INFO - TEST-PASS | browser/base/content/test/trackingUI/browser_trackingUI_socialtracking.js | trackers are detected -
[task 2019-08-03T12:35:02.446Z] 12:35:02 INFO - TEST-PASS | browser/base/content/test/trackingUI/browser_trackingUI_socialtracking.js | icon box is visible -
[task 2019-08-03T12:35:02.446Z] 12:35:02 INFO - TEST-PASS | browser/base/content/test/trackingUI/browser_trackingUI_socialtracking.js | Shows an exception when appropriate -
[task 2019-08-03T12:35:02.448Z] 12:35:02 INFO - Console message: [JavaScript Warning: "The resource at “https://socialtracking.example.com/” was blocked because content blocking is enabled." {file: "http://example.org/browser/browser/base/content/test/trackingUI/trackingPage.html" line: 0}]
[task 2019-08-03T12:35:02.450Z] 12:35:02 INFO - Console message: [JavaScript Error: "Argument not a number"]
[task 2019-08-03T12:35:02.451Z] 12:35:02 INFO - Console message: [JavaScript Error: "Argument not a number"]
[task 2019-08-03T12:35:02.452Z] 12:35:02 INFO - Received onContentBlockingEvent event 1 of 1
[task 2019-08-03T12:35:02.453Z] 12:35:02 INFO - Buffered messages logged at 12:32:03
[task 2019-08-03T12:35:02.460Z] 12:35:02 INFO - TEST-PASS | browser/base/content/test/trackingUI/browser_trackingUI_socialtracking.js | socialtrackings are not detected -
[task 2019-08-03T12:35:02.461Z] 12:35:02 INFO - TEST-PASS | browser/base/content/test/trackingUI/browser_trackingUI_socialtracking.js | icon box is visible regardless the exception -
[task 2019-08-03T12:35:02.462Z] 12:35:02 INFO - Buffered messages logged at 12:33:31
[task 2019-08-03T12:35:02.463Z] 12:35:02 INFO - Longer timeout required, waiting longer... Remaining timeouts: 1
[task 2019-08-03T12:35:02.464Z] 12:35:02 INFO - Buffered messages finished
[task 2019-08-03T12:35:02.465Z] 12:35:02 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/trackingUI/browser_trackingUI_socialtracking.js | Test timed out -
[task 2019-08-03T12:35:02.467Z] 12:35:02 INFO - GECKO(1937) | MEMORY STAT | vsize 20975026MB | residentFast 1183MB
[task 2019-08-03T12:35:02.468Z] 12:35:02 INFO - TEST-OK | browser/base/content/test/trackingUI/browser_trackingUI_socialtracking.js | took 180286ms
[task 2019-08-03T12:35:02.469Z] 12:35:02 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-08-03T12:35:02.472Z] 12:35:02 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/trackingUI/browser_trackingUI_socialtracking.js | Found a tab after previous test timed out: http://example.org/browser/browser/base/content/test/trackingUI/trackingPage.html -
[task 2019-08-03T12:35:02.475Z] 12:35:02 INFO - checking window state
[task 2019-08-03T12:35:02.476Z] 12:35:02 INFO - GECKO(1937) | JavaScript error: resource://testing-common/PromiseTestUtils.jsm, line 112: uncaught exception: Object
[task 2019-08-03T12:35:02.481Z] 12:35:02 INFO - Console message: [JavaScript Error: "info is not defined" {file: "chrome://mochitests/content/browser/browser/base/content/test/trackingUI/head.js" line: 89}]
[task 2019-08-03T12:35:02.482Z] 12:35:02 INFO - onContentBlockingEvent@chrome://mochitests/content/browser/browser/base/content/test/trackingUI/head.js:89:9
[task 2019-08-03T12:35:02.483Z] 12:35:02 INFO - callListeners@chrome://browser/content/tabbrowser.js:826:31

Comment 4

[Intermittent Failures Robot]

24 failures in 4439 pushes (0.005 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 24

Platform breakdown:

• macosx1014-64: 2
• windows7-32: 2
• macosx1014-64-devedition: 2
• macosx1014-64-shippable: 2
• windows10-64: 2
• windows10-64-qr: 1
• linux64-shippable: 3
• windows7-32-devedition: 2
• windows10-64-devedition: 1
• windows10-64-shippable: 1
• windows10-64-shippable-qr: 1
• windows7-32-shippable: 2
• linux64: 2
• linux64-devedition: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1570984&startday=2019-07-29&endday=2019-08-04&tree=all

Comment 5

[Gary Chen [:xeonchen]]

(In reply to Bogdan Tara[:bogdan_tara] from comment #3)

Sadly, i still see this on the late beta simulation:

I'm still figuring it out, sorry it took more time than I expected.

It's weird for me because both browser_trackingUI_socialtracking.js and browser_trackingUI_socialtracking_doorhanger.js are both timed out, where browser_trackingUI_socialtracking.js is 90+% similar to other test file such as browser_trackingUI_cryptominers.js.

Comment 6

[Gary Chen [:xeonchen]]

Attachment: log.txt

It was blocked on the second time it calls waitForContentBlockingEvent because socialtracking.example.com is not blocked.

Comment 7

[Gary Chen [:xeonchen]]

Attachment: 0001-test.patch

Hi Baku, I found that the host defined in urlclassifier.features.socialtracking.blacklistHosts will not be blocked when the second time it opens the host, that causes the test timeout.

But if I use urlclassifier.features.cryptomining.annotate.blacklistHosts and privacy.trackingprotection.cryptomining.enabled instead, it works well without blocking (and of course the result is not correct).

Any idea what's the difference between beta and central?

Comment 8

[Andrea Marchesini [:baku]]

Can you provide a full test? You are testing social-tracking protection, correct?

Comment 9

[Gary Chen [:xeonchen]]

(In reply to Andrea Marchesini [:baku] from comment #8)

Can you provide a full test? You are testing social-tracking protection, correct?

The test is browser/base/content/test/trackingUI/browser_trackingUI_socialtracking.js running on beta (based on :bogdan_tara's revision).
I have a branch on github.

Is this what you need?

Comment 10

[Andreea Pavel [:apavel]]

Importing this patch makes the failures go away:

Early beta: https://treeherder.mozilla.org/#/jobs?repo=try&resultStatus=retry%2Ctestfailed%2Cbusted%2Cexception%2Cusercancel%2Crunnable&revision=954daa1cf04576f8a464e418dee2b3ef9082b8e6&searchStr=browser%2Cchrome&selectedJob=260103614

Late beta: https://treeherder.mozilla.org/#/jobs?repo=try&resultStatus=testfailed%2Cbusted%2Cexception%2Cretry%2Cusercancel%2Crunnable&revision=665978499f39c9a21e12992818a5a46a6821d96c&searchStr=browser-chrome&selectedJob=260105801

Comment 11

[Andrea Marchesini [:baku]]

Hi Baku, I found that the host defined in urlclassifier.features.socialtracking.blacklistHosts will not be blocked when the second time it opens the host, that causes the test timeout.

You say that the first time it works, but the second time it doesn't? Are you able to test it locally and enable the url-classifier log?
I suspect there is a simple pref to change somewhere...

Comment 12

[Andrea Marchesini [:baku]]

Comment on attachment 9083326 [details] [diff] [review]
0001-test.patch

Review of attachment 9083326 [details] [diff] [review]:
-----------------------------------------------------------------

I see, but we cannot change this test in this way. It will test something else... See my previous comment about enabling logging.

Comment 13

[Gary Chen [:xeonchen]]

(In reply to Andrea Marchesini [:baku] from comment #11)

You say that the first time it works, but the second time it doesn't? Are you able to test it locally and enable the url-classifier log?
I suspect there is a simple pref to change somewhere...
I agree.

Is attachment 9083137 [details] helping? Please tell me if you need any more log to be enabled :)

Comment 14

[Oana Pop-Rus]

The second patch doesn't apply cleanly, by itself and also with the first patch on top.

Gary could you please merge into one patch when you have the final version?

Thank you.

Here is the .rej file with the second patch on top of the first one:
--- browser_trackingUI_socialtracking.js
+++ browser_trackingUI_socialtracking.js
@@ -4,30 +4,29 @@
use strict;

const TRACKING_PAGE =
http://example.org/browser/browser/base/content/test/trackingUI/trackingPage.html;

add_task(async function setup() {
await SpecialPowers.pushPrefEnv({
set: [
-[privacy.trackingprotection.socialtracking.enabled, true],
-[privacy.trackingprotection.socialtracking.annotate.enabled, true],
+[privacy.trackingprotection.cryptomining.enabled, true],
+[privacy.trackingprotection.cryptomining.annotate.enabled, true],
+
[
-urlclassifier.features.socialtracking.blacklistHosts,
+urlclassifier.features.cryptomining.blacklistHosts,
socialtracking.example.com,
],
[
-urlclassifier.features.socialtracking.annotate.blacklistHosts,
+urlclassifier.features.cryptomining.annotate.blacklistHosts,
socialtracking.example.com,
],
[privacy.trackingprotection.enabled, false],
[privacy.trackingprotection.annotate_channels, false],
-[privacy.trackingprotection.cryptomining.enabled, false],
-[privacy.trackingprotection.cryptomining.annotate.enabled, false],
[privacy.trackingprotection.fingerprinting.enabled, false],
[privacy.trackingprotection.fingerprinting.annotate.enabled, false],
],
});
});

async function testIdentityState(hasException) {
let promise = BrowserTestUtils.openNewForegroundTab({

Comment 15

[Gary Chen [:xeonchen]]

(In reply to Oana Pop-Rus from comment #14)

The second patch doesn't apply cleanly, by itself and also with the first patch on top.
Gary could you please merge into one patch when you have the final version?

Oops, you don't want that patch.
It's just kind of my "description" for :baku to understand what is happening.

Comment 16

[Cosmin Sabou [:CosminS]]

Gary, this works in most recent beta-sims: https://treeherder.mozilla.org/#/jobs?repo=try&group_state=expanded&resultStatus=success%2Ctestfailed%2Cbusted%2Cexception&classifiedState=unclassified&revision=9cc65dcfd6d8236d67d74fb177cb6754e50f572a&searchStr=os%2Cx%2C10.14%2Cdebug%2Cmochitests%2Ctest-macosx1014-64%2Fdebug-mochitest-browser-chrome-e10&selectedJob=261105605
Used these changes https://hg.mozilla.org/try/rev/afa30ff1c1c3b5350361be256d8d5b483ba07cd5 because of conflicts while applying the patch.
Do you mind rebasing the patch and landing it on integration? Thank you

Comment 17

[Gary Chen [:xeonchen]]

(In reply to Cosmin Sabou [:CosminS] from comment #16)

Gary, this works in most recent beta-sims: https://treeherder.mozilla.org/#/jobs?repo=try&group_state=expanded&resultStatus=success%2Ctestfailed%2Cbusted%2Cexception&classifiedState=unclassified&revision=9cc65dcfd6d8236d67d74fb177cb6754e50f572a&searchStr=os%2Cx%2C10.14%2Cdebug%2Cmochitests%2Ctest-macosx1014-64%2Fdebug-mochitest-browser-chrome-e10&selectedJob=261105605
Used these changes https://hg.mozilla.org/try/rev/afa30ff1c1c3b5350361be256d8d5b483ba07cd5 because of conflicts while applying the patch.
Do you mind rebasing the patch and landing it on integration? Thank you

No problem :)

Comment 18

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/2b8dd6696138
separate large tests; r=johannh,kmag

Comment 19

[Alexandru Michis [:malexandru]]

https://hg.mozilla.org/mozilla-central/rev/2b8dd6696138

Comment 20

[Cosmin Sabou [:CosminS]]

Verified in todays beta-sims: https://treeherder.mozilla.org/#/jobs?repo=try&resultStatus=success%2Ctestfailed%2Cbusted%2Cexception%2Cretry%2Cusercancel%2Crunnable&revision=165fd1931de3750a6a82010c50c31a08940769f0&searchStr=os%2Cx%2C10.14%2Cdebug%2Cmochitests%2Ctest-macosx1014-64%2Fdebug-mochitest-browser-chrome-e10s