Closed Bug 1369395 Opened 7 years ago Closed 6 years ago

Intermittent dom/base/test/test_intersectionobservers.html | does trigger if target does not intersect when observing begins [observe] - got +0, expected 1

Categories

(Core :: Layout, defect)

Product:
Core
Component:
Layout
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla62
Tracking Flags:
Tracking Status
firefox62 --- fixed

People

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

References

Details

(Keywords: intermittent-failure, Whiteboard: [retriggered][stockwell fixed:other])

Attachments

(1 file)

Bug 1369395 - Change test_intersectionobservers.html to put test callbacks through the event queue twice to ensure that we get processed after any relevant intersection callbacks.
59 bytes, text/x-review-board-request
mstange
: review+
Details 
Over the last 7 days there are 35 failures on this bug. These happen only on android-4-3-armv7-api16.
Here is the most recent log example: https://treeherder.mozilla.org/logviewer.html#?job_id=180360257&repo=mozilla-inbound&lineNumber=1749

[task 2018-05-26T05:57:24.585Z] 05:57:24     INFO -  164 INFO TEST-PASS | dom/base/test/test_intersectionobservers.html | triggers with the correct arguments [observe]
[task 2018-05-26T05:57:24.585Z] 05:57:24     INFO -  165 INFO TEST-PASS | dom/base/test/test_intersectionobservers.html | triggers with the correct arguments [observe]
[task 2018-05-26T05:57:24.586Z] 05:57:24     INFO -  166 INFO TEST-PASS | dom/base/test/test_intersectionobservers.html | triggers with the correct arguments [observe]
[task 2018-05-26T05:57:24.587Z] 05:57:24     INFO -  167 INFO TEST-PASS | dom/base/test/test_intersectionobservers.html | triggers with the correct arguments [observe]
[task 2018-05-26T05:57:24.587Z] 05:57:24     INFO -  Buffered messages finished
[task 2018-05-26T05:57:24.587Z] 05:57:24     INFO -  168 INFO TEST-UNEXPECTED-FAIL | dom/base/test/test_intersectionobservers.html | does trigger if target does not intersect when observing begins [observe] - got +0, expected 1
[task 2018-05-26T05:57:24.588Z] 05:57:24     INFO -      SimpleTest.is@SimpleTest/SimpleTest.js:312:5
[task 2018-05-26T05:57:24.589Z] 05:57:24     INFO -      fn@dom/base/test/test_intersectionobservers.html:91:13
[task 2018-05-26T05:57:24.589Z] 05:57:24     INFO -      @dom/base/test/test_intersectionobservers.html:334:11
Flags: needinfo?(mreavy)
(In reply to Eliza Balazs [:ebalazs_] from comment #27)
> Did some retriggers (2 failures out of 22 jobs) and found the push that
> started this failure:
>  https://treeherder.mozilla.org/#/jobs?repo=autoland&filter-searchStr=debug-
> mochitest-
> 6%20android&tochange=51b77a6408786769c5ec8695a13d5e3591f6fd85&fromchange=9260
> cc524bb54d9318075578488de8a6f40677eb&selectedJob=179305916
> 
> https://hg.mozilla.org/integration/autoland/rev/
> fd84333ffe760d3fdb151e2d79316c69743f3129
> 
> https://bugzilla.mozilla.org/show_bug.cgi?id=1371668
> 
> :gbrown, :jmaher, can you please have a look at this?

Thanks :ebalazs. I retriggered more, giving us these results:

https://treeherder.mozilla.org/#/jobs?repo=autoland&filter-searchStr=debug-mochitest-6%20android&tochange=51b77a6408786769c5ec8695a13d5e3591f6fd85&fromchange=96c52800d2ec78f56dbcbcb8fdf15b145941a131

It looks to me like these failures may have worsened significantly, at least on Android/debug, with bug 1371668.

(However, note that there was at least one earlier failure of the same test with a different failure message 2 pushes earlier, at https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=5009e8a9734cd6bddc7a3a443dff0f411314e233.)

:mattwoodrow -- Might these failures in test_intersectionobservers.html be related to your changes in bug 1371668?
Flags: needinfo?(gbrown) → needinfo?(matt.woodrow)
Thanks, Rob!  

Current status: Matt is planning to take a look tomorrow.
Flags: needinfo?(mreavy)
The failing piece of the test is setting an intersection observer to observe an Element that doesn't currently intersect, and then moves it such that it does intersect [1].

It then waits for the first rAF callback that happens at least 300ms after this. In the failing case, this is also the first rAF callback.

rAF callbacks are fired from nsRefreshDriver::Tick, and before we run nsRefreshDriver::UpdateIntersectionObservers, so at this point no intersection updates have been computed. The test code schedules the actual check to happen 'soon' [2], which puts an event into the event queue.

Then we run UpdateIntersectionObservations, which computes the intersection, queues it, and then we call nsIDocument::ScheduleIntersectionObserverNotification() which also posts an event to the event queue to run our notification callback in the test.

Now the test code event is in the event queue before the intersection notification, and when it runs, we fail because we haven't received any intersection notifications.

Bug 1371668 changes the timings of when nsRefreshDriver::Tick runs, so it likely just made the case where the first rAF received was after the 300ms stand-down period.

I think we can drop the 300ms, but instead have two nested executeSoon call to ensure that we're scheduled after notifications have fired.

[1] https://searchfox.org/mozilla-central/source/dom/base/test/test_intersectionobservers.html#325
[2] https://searchfox.org/mozilla-central/source/dom/base/test/test_intersectionobservers.html#71
Assignee: nobody → matt.woodrow
There have been 47 failures in the last week.

Failures per platform and build type:
android-4-3-armv7-api16: 46 (44 failures on debug & 2 failures on opt)
linux64-qr / debug: 1

Recent log file:
https://treeherder.mozilla.org/logviewer.html#?job_id=182402305&repo=mozilla-central&lineNumber=1368


Snippet with the failure:

[task 2018-06-07T22:57:18.963Z] 22:57:18     INFO -  106 INFO TEST-PASS | dom/base/test/test_intersectionobservers.html | triggers with the correct arguments [observe]
[task 2018-06-07T22:57:18.964Z] 22:57:18     INFO -  107 INFO TEST-PASS | dom/base/test/test_intersectionobservers.html | triggers with the correct arguments [observe]
[task 2018-06-07T22:57:18.964Z] 22:57:18     INFO -  Buffered messages finished
[task 2018-06-07T22:57:18.965Z] 22:57:18     INFO -  108 INFO TEST-UNEXPECTED-FAIL | dom/base/test/test_intersectionobservers.html | does trigger if target does not intersect when observing begins [observe] - got +0, expected 1
[task 2018-06-07T22:57:18.966Z] 22:57:18     INFO -      SimpleTest.is@SimpleTest/SimpleTest.js:312:5
[task 2018-06-07T22:57:18.966Z] 22:57:18     INFO -      fn@dom/base/test/test_intersectionobservers.html:91:13
[task 2018-06-07T22:57:18.967Z] 22:57:18     INFO -      @dom/base/test/test_intersectionobservers.html:334:11
[task 2018-06-07T22:57:29.381Z] 22:57:29     INFO -  109 INFO TEST-PASS | dom/base/test/test_intersectionobservers.html | does not trigger if target is not a descendant of the intersection root in the containing block chain [observe]
Flags: needinfo?(matt.woodrow)
Whiteboard: [retriggered] → [retriggered][stockwell needswork]
This is currently waiting for my review. I'm hoping to get to it soon.
Flags: needinfo?(matt.woodrow)
Comment on attachment 8982078 [details]
Bug 1369395 - Change test_intersectionobservers.html to put test callbacks through the event queue twice to ensure that we get processed after any relevant intersection callbacks.

https://reviewboard.mozilla.org/r/248122/#review257318

Much better, thanks!
Attachment #8982078 - Flags: review?(mstange) → review+
Pushed by mwoodrow@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/c0c1dea29b17
Change test_intersectionobservers.html to put test callbacks through the event queue twice to ensure that we get processed after any relevant intersection callbacks. r=mstange
https://hg.mozilla.org/mozilla-central/rev/c0c1dea29b17
Status: NEW → RESOLVED
Closed: 6 years ago
status-firefox62: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla62
Whiteboard: [retriggered][stockwell needswork] → [retriggered][stockwell fixed:other]
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: