Closed Bug 1503843 Opened 11 months ago Closed 11 months ago

Perma Linux x64 debug M-sw-e10s toolkit/components/antitracking/test/browser/browser_subResources.js | Correct repeat count reported - Got 7, expected 6

Categories

(Core :: DOM: Security, defect, P5)

defect

Tracking

()

RESOLVED FIXED
mozilla65
Tracking Status
firefox65 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: ehsan)

Details

(Keywords: intermittent-failure)

Filed by: ebalazs [at] mozilla.com

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

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

TEST-PASS | toolkit/components/antitracking/test/browser/browser_subResources.js | Correct blocking status reported - 
[task 2018-11-01T10:28:36.272Z] 10:28:36     INFO - Buffered messages finished
[task 2018-11-01T10:28:36.278Z] 10:28:36     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/antitracking/test/browser/browser_subResources.js | Correct repeat count reported - Got 7, expected 6
[task 2018-11-01T10:28:36.282Z] 10:28:36     INFO - Stack trace:
[task 2018-11-01T10:28:36.283Z] 10:28:36     INFO - chrome://mochikit/content/browser-test.js:test_is:1300
[task 2018-11-01T10:28:36.283Z] 10:28:36     INFO - chrome://mochitests/content/browser/toolkit/components/antitracking/test/browser/browser_subResources.js:null:168
[task 2018-11-01T10:28:36.284Z] 10:28:36     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1098
[task 2018-11-01T10:28:36.285Z] 10:28:36     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1089
[task 2018-11-01T10:28:36.285Z] 10:28:36     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:987
[task 2018-11-01T10:28:36.285Z] 10:28:36     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:795
[task 2018-11-01T10:28:36.286Z] 10:28:36     INFO - TEST-PASS | toolkit/components/antitracking/test/browser/browser_subResources.js | Correct blocking type reported - 
[task 2018-11-01T10:28:36.288Z] 10:28:36     INFO - TEST-PASS | toolkit/components/antitracking/test/browser/browser_subResources.js | Correct blocking status reported - 
[task 2018-11-01T10:28:36.288Z] 10:28:36     INFO - TEST-PASS | toolkit/components/antitracking/test/browser/browser_subResources.js | Correct repeat count reported - 
[task 2018-11-01T10:28:36.289Z] 10:28:36     INFO - Removing the tab
[task 2018-11-01T10:28:36.290Z] 10:28:36     INFO - Leaving test bound 
[task 2018-11-01T10:28:36.290Z] 10:28:36     INFO - Entering test bound 
[task 2018-11-01T10:28:36.291Z] 10:28:36     INFO - Cleaning up.
[task 2018-11-01T10:28:36.292Z] 10:28:36     INFO - GECKO(5463) | [Child 5565, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, false) failed with result 0x80004005: file /builds/worker/workspace/build/src/docshell/shistory/nsSHistory.cpp, line 1291
[task 2018-11-01T10:28:36.292Z] 10:28:36     INFO - GECKO(5463) | [Child 5565, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, false) failed with result 0x80004005: file /builds/worker/workspace/build/src/docshell/shistory/nsSHistory.cpp, line 1291
[task 2018-11-01T10:28:36.293Z] 10:28:36     INFO - GECKO(5463) | [Parent 5463, Main Thread] WARNING: Suboptimal indexes for the SQL statement 0x7fdadbb4e710 (http://mzl.la/1FuID0j).: file /builds/worker/workspace/build/src/storage/mozStoragePrivateHelpers.cpp, line 114
[task 2018-11-01T10:28:36.294Z] 10:28:36     INFO - Leaving test bound 
[task 2018-11-01T10:28:36.295Z] 10:28:36     INFO - GECKO(5463) | MEMORY STAT | vsize 1953MB | residentFast 428MB | heapAllocated 122MB
[task 2018-11-01T10:28:36.296Z] 10:28:36     INFO - TEST-OK | toolkit/components/antitracking/test/browser/browser_subResources.js | took 5369ms
[task 2018-11-01T10:28:36.296Z] 10:28:36     INFO - GECKO(5463) | ++DOCSHELL 0x7f8546859000 == 11 [pid = 5565] [id = {0e4be070-4810-4124-b690-2d879190a939}]
[task 2018-11-01T10:28:36.297Z] 10:28:36     INFO - GECKO(5463) | ++DOMWINDOW == 62 (0x7f854471be00) [pid = 5565] [serial = 1054] [outer = (nil)]
[task 2018-11-01T10:28:36.298Z] 10:28:36     INFO - checking window state
[task 2018-11-01T10:28:36.299Z] 10:28:36     INFO - GECKO(5463) | ++DOMWINDOW == 63 (0x7f8547bab800) [pid = 5565] [serial = 1055] [outer = 0x7f854471be00]
Summary: Perma toolkit/components/antitracking/test/browser/browser_subResources.js | Correct repeat count reported - Got 7, expected 6 → Perma Linux x64 debug M-sw-e10s toolkit/components/antitracking/test/browser/browser_subResources.js | Correct repeat count reported - Got 7, expected 6
Hmm, another case where this configuration behaves differently than our default for reasons that I don't understand.  Disabling the test on this configuration, CCing asuth for visibility.

(Hopefully someone some day will look into re-enabling all of these disabled tests.)
Depends on: 1503697
Flags: needinfo?(ehsan)
Pushed by eakhgari@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/36cce9ce1de9
Disable browser_subResources.js for M-sw-e10s since it fails there for unknown reasons
If I understand the failure, the test is saying that the tracking protection contentBlockingLog has one more line than expected.  And I don't see any ServiceWorkers intentionally involved in this test.

This would somewhat suggest you've got a ServiceWorker registration hanging around that should not be hanging around and that this induced an additional tracking protection check.  (Like we went from nsHttpChannel -> intercepted channel -> nsHttpChannel for the navigation load.)  It'd be easier to get at if there was an easy way to do an A/B on "good log" versus "bad log", but that's really the story of examining test failure logs, isn't it? :)

We will definitely be clearing out the explicit disablings!
(In reply to Andrew Sutherland [:asuth] from comment #5)
> If I understand the failure, the test is saying that the tracking protection
> contentBlockingLog has one more line than expected.  And I don't see any
> ServiceWorkers intentionally involved in this test.

Right.

> This would somewhat suggest you've got a ServiceWorker registration hanging
> around that should not be hanging around and that this induced an additional
> tracking protection check.

Don't we have a check in between each mochitest to ensure no SW registrations get leaked over to the next test?  The one added in bug 1237363.

> (Like we went from nsHttpChannel -> intercepted
> channel -> nsHttpChannel for the navigation load.)  It'd be easier to get at
> if there was an easy way to do an A/B on "good log" versus "bad log", but
> that's really the story of examining test failure logs, isn't it? :)
> 
> We will definitely be clearing out the explicit disablings!

FWIW this can easily be figured out by console.log-ing the log here: https://searchfox.org/mozilla-central/rev/39cb1e96cf97713c444c5a0404d4f84627aee85d/toolkit/components/antitracking/test/browser/browser_subResources.js#159
No longer depends on: 1503697
(In reply to :Ehsan Akhgari from comment #6)
> Don't we have a check in between each mochitest to ensure no SW
> registrations get leaked over to the next test?  The one added in bug
> 1237363.

We do (and thank you for adding it! :), but it ignores pending uninstalls.  So you're absolutely right that the navigation interception shouldn't be able to happen.  But you could totally have a bunch of ServiceWorkers hanging out in the background doing stuff as long as they have extended lifetime promises keeping them alive and haven't timed out yet, thereby allowing the Clear Registration algorithm to run.  (Or are controlling a document, which they shouldn't be able to do due to other inter-test invariants.)  This is all hand-waving, mind you.  I just like to leave theories for my future self.
https://hg.mozilla.org/mozilla-central/rev/36cce9ce1de9
Status: NEW → RESOLVED
Closed: 11 months ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla65
(In reply to Andrew Sutherland [:asuth] from comment #7)
> (In reply to :Ehsan Akhgari from comment #6)
> > Don't we have a check in between each mochitest to ensure no SW
> > registrations get leaked over to the next test?  The one added in bug
> > 1237363.
> 
> We do (and thank you for adding it! :), but it ignores pending uninstalls. 
> So you're absolutely right that the navigation interception shouldn't be
> able to happen.  But you could totally have a bunch of ServiceWorkers
> hanging out in the background doing stuff as long as they have extended
> lifetime promises keeping them alive and haven't timed out yet, thereby
> allowing the Clear Registration algorithm to run.  (Or are controlling a
> document, which they shouldn't be able to do due to other inter-test
> invariants.)  This is all hand-waving, mind you.  I just like to leave
> theories for my future self.

Ah, yes.  That makes a lot of sense.

Actually, based on what I know about the antitracking side of things (which is pretty deterministic, so I doubt there's an unexpected request coming out of nowhere here) I do suspect that your theory here correct.  Indeed, looking at the browser.ini in this file, at least browser_blockingServiceWorkers.js runs before this test and that test does register a few service workers.

Hopefully these notes will help with the future debugging.  :-)
Assignee: nobody → ehsan
You need to log in before you can comment on or make changes to this bug.