Closed Bug 1570984 Opened 5 years ago Closed 5 years ago

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

Categories

(Firefox :: Protections UI, defect, P1)

Product:
Firefox
Component:
Protections UI
Type:
defect

Tracking

()

Status:
VERIFIED FIXED
Milestone:
Firefox 70
Tracking Flags:
Tracking Status
firefox-esr60 --- unaffected
firefox-esr68 --- unaffected
firefox68 --- unaffected
firefox69 --- unaffected
firefox70 + verified

People

(Reporter: aiakab, Assigned: xeonchen)

References

(Regression)

Details

(Keywords: regression, Whiteboard: [skyline][stp])

Attachments

(3 files)

Bug 1570984 - separate large tests;
47 bytes, text/x-phabricator-request
Details | Review
log.txt
282.04 KB, text/plain
Details
0001-test.patch
1.84 KB, patch
baku
: feedback-
Details | Diff | Splinter Review
status-firefox68: --- → unaffected
status-firefox69: --- → unaffected
status-firefox70: --- → affected
tracking-firefox70: --- → ?
Flags: needinfo?(xeonchen)
Regressed by: 1567896

(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.

Assignee: nobody → xeonchen
Flags: needinfo?(xeonchen)
Priority: -- → P1

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

Flags: needinfo?(xeonchen)
Status: NEW → ASSIGNED
Whiteboard: [skyline][stp]

(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.

Flags: needinfo?(xeonchen)
Attached file log.txt —

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

Attached patch 0001-test.patch — — Splinter Review

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?

Attachment #9083326 - Flags: feedback?(amarchesini)

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

Flags: needinfo?(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?

Flags: needinfo?(xeonchen) → needinfo?(amarchesini)

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...

Flags: needinfo?(amarchesini)
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.
Attachment #9083326 - Flags: feedback?(amarchesini) → feedback-

(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 :)

Flags: needinfo?(amarchesini)

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({

Flags: needinfo?(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.

Flags: needinfo?(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 :)

Flags: needinfo?(xeonchen)
Pushed by xeonchen@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/2b8dd6696138
separate large tests; r=johannh,kmag

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

Status: ASSIGNED → RESOLVED
Closed: 5 years ago
status-firefox70: affected → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 70
Flags: needinfo?(amarchesini)
Has Regression Range: --- → yes
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: