Intermittent various failures in test_animation_observers.html | [single_transition_reversed] getAnimationPlayers().length after transition reversal - got 0, expected 1 | [multiple_transitions] number of running AnimationPlayers - got 0, expected 3

RESOLVED FIXED in Firefox 39

Status

()

defect
RESOLVED FIXED
5 years ago
4 years ago

People

(Reporter: KWierso, Assigned: heycam)

Tracking

({intermittent-failure})

39 Branch
mozilla39
x86_64
macOS
Points:
---

Firefox Tracking Flags

(firefox37 unaffected, firefox38 unaffected, firefox39 fixed, firefox40 fixed, firefox-esr31 unaffected)

Details

Attachments

(2 attachments)

13:54:03 INFO - 691 INFO TEST-PASS | dom/animation/test/chrome/test_animation_observers.html | [single_transition_cancelled_noninterpolable] records after transition start - record[0].addedAnimations length
13:54:03 INFO - 692 INFO TEST-PASS | dom/animation/test/chrome/test_animation_observers.html | [single_transition_cancelled_noninterpolable] records after transition start - record[0].addedAnimations contains expected AnimationPlayer
13:54:03 INFO - 693 INFO TEST-PASS | dom/animation/test/chrome/test_animation_observers.html | [single_transition_cancelled_noninterpolable] records after transition start - record[0].changedAnimations length
13:54:03 INFO - 694 INFO TEST-PASS | dom/animation/test/chrome/test_animation_observers.html | [single_transition_cancelled_noninterpolable] records after transition start - record[0].removedAnimations length
13:54:03 INFO - 695 INFO TEST-PASS | dom/animation/test/chrome/test_animation_observers.html | [single_transition_cancelled_noninterpolable] records after transition end - number of records
13:54:03 INFO - 696 INFO TEST-PASS | dom/animation/test/chrome/test_animation_observers.html | [single_transition_cancelled_noninterpolable] records after transition end - record[0].addedAnimations length
13:54:03 INFO - 697 INFO TEST-PASS | dom/animation/test/chrome/test_animation_observers.html | [single_transition_cancelled_noninterpolable] records after transition end - record[0].changedAnimations length
13:54:03 INFO - 698 INFO TEST-PASS | dom/animation/test/chrome/test_animation_observers.html | [single_transition_cancelled_noninterpolable] records after transition end - record[0].removedAnimations length
13:54:03 INFO - 699 INFO TEST-PASS | dom/animation/test/chrome/test_animation_observers.html | [single_transition_cancelled_noninterpolable] records after transition end - record[0].removedAnimations contains expected AnimationPlayer
13:54:03 INFO - 700 INFO TEST-PASS | dom/animation/test/chrome/test_animation_observers.html | [single_transition_reversed] getAnimationPlayers().length after transition start
13:54:03 INFO - 701 INFO TEST-PASS | dom/animation/test/chrome/test_animation_observers.html | [single_transition_reversed] records after transition start - number of records
13:54:03 INFO - 702 INFO TEST-PASS | dom/animation/test/chrome/test_animation_observers.html | [single_transition_reversed] records after transition start - record[0].addedAnimations length
13:54:03 INFO - 703 INFO TEST-PASS | dom/animation/test/chrome/test_animation_observers.html | [single_transition_reversed] records after transition start - record[0].addedAnimations contains expected AnimationPlayer
13:54:03 INFO - 704 INFO TEST-PASS | dom/animation/test/chrome/test_animation_observers.html | [single_transition_reversed] records after transition start - record[0].changedAnimations length
13:54:03 INFO - 705 INFO TEST-PASS | dom/animation/test/chrome/test_animation_observers.html | [single_transition_reversed] records after transition start - record[0].removedAnimations length
13:54:03 INFO - 706 INFO TEST-UNEXPECTED-FAIL | dom/animation/test/chrome/test_animation_observers.html | [single_transition_reversed] getAnimationPlayers().length after transition reversal - got 0, expected 1
13:54:03 INFO - 707 INFO TEST-PASS | dom/animation/test/chrome/test_animation_observers.html | [single_transition_reversed] records after transition reversal - number of records
13:54:03 INFO - 708 INFO TEST-UNEXPECTED-FAIL | dom/animation/test/chrome/test_animation_observers.html | [single_transition_reversed] records after transition reversal - record[0].addedAnimations length - got 0, expected 1
13:54:03 INFO - 709 INFO TEST-PASS | dom/animation/test/chrome/test_animation_observers.html | [single_transition_reversed] records after transition reversal - record[0].changedAnimations length
13:54:03 INFO - 710 INFO TEST-PASS | dom/animation/test/chrome/test_animation_observers.html | [single_transition_reversed] records after transition reversal - record[0].removedAnimations length
13:54:03 INFO - 711 INFO TEST-PASS | dom/animation/test/chrome/test_animation_observers.html | [single_transition_reversed] records after transition reversal - record[0].removedAnimations contains expected AnimationPlayer
13:54:03 INFO - 712 INFO TEST-UNEXPECTED-FAIL | dom/animation/test/chrome/test_animation_observers.html | [single_transition_reversed] records after transition end - number of records - got 0, expected 1
13:54:03 INFO - 713 INFO TEST-PASS | dom/animation/test/chrome/test_animation_observers.html | [multiple_transitions] getAnimationPlayers().length after transition starts
13:54:03 INFO - 714 INFO TEST-PASS | dom/animation/test/chrome/test_animation_observers.html | [multiple_transitions] records after transition starts - number of records
13:54:03 INFO - 715 INFO TEST-PASS | dom/animation/test/chrome/test_animation_observers.html | [multiple_transitions] records after transition starts - record[0].addedAnimations length
13:54:03 INFO - 716 INFO TEST-PASS | dom/animation/test/chrome/test_animation_observers.html | [multiple_transitions] records after transition starts - record[0].addedAnimations contains expected AnimationPlayer
13:54:03 INFO - 717 INFO TEST-PASS | dom/animation/test/chrome/test_animation_observers.html | [multiple_transitions] records after transition starts - record[0].addedAnimations contains expected AnimationPlayer
13:54:03 INFO - 718 INFO TEST-PASS | dom/animation/test/chrome/test_animation_observers.html | [multiple_transitions] records after transition starts - record[0].addedAnimations contains expected AnimationPlayer
13:54:03 INFO - 719 INFO TEST-PASS | dom/animation/test/chrome/test_animation_observers.html | [multiple_transitions] records after transition starts - record[0].changedAnimations length
13:54:03 INFO - 720 INFO TEST-PASS | dom/animation/test/chrome/test_animation_observers.html | [multiple_transitions] records after transition starts - record[0].removedAnimations length
13:54:03 INFO - 721 INFO TEST-PASS | dom/animation/test/chrome/test_animation_observers.html | [multiple_transitions] number of running AnimationPlayers
Assignee: nobody → cam
Status: NEW → ASSIGNED
Posted patch patchSplinter Review
Let's try this.
Attachment #8581060 - Flags: review?(bbirtles)
Attachment #8581060 - Flags: review?(bbirtles) → review+
https://hg.mozilla.org/mozilla-central/rev/5ae6881f492e
Status: ASSIGNED → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla39
Maybe we should log the playState and currentTime of the three AnimationPlayers to see what's going on.
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
jwatt, you've been doing animation-related work lately too, right? Any ideas?
Flags: needinfo?(jwatt)
From that failing run:

TEST-PASS | dom/animation/test/chrome/test_animation_observers.html | [multiple_transitions:subtree] getAnimations().length after transition starts
animation states: pending,pending,pending
animation times: 0,0,0
TEST-PASS | dom/animation/test/chrome/test_animation_observers.html | [multiple_transitions:subtree] records after transition starts - number of records
TEST-PASS | dom/animation/test/chrome/test_animation_observers.html | [multiple_transitions:subtree] records after transition starts - record[0].addedAnimations length
TEST-PASS | dom/animation/test/chrome/test_animation_observers.html | [multiple_transitions:subtree] records after transition starts - record[0].addedAnimations contains expected Animation
TEST-PASS | dom/animation/test/chrome/test_animation_observers.html | [multiple_transitions:subtree] records after transition starts - record[0].addedAnimations contains expected Animation
19:52:32 INFO - 771 INFO TEST-PASS | dom/animation/test/chrome/test_animation_observers.html | [multiple_transitions:subtree] records after transition starts - record[0].addedAnimations contains expected Animation
TEST-PASS | dom/animation/test/chrome/test_animation_observers.html | [multiple_transitions:subtree] records after transition starts - record[0].changedAnimations length
TEST-PASS | dom/animation/test/chrome/test_animation_observers.html | [multiple_transitions:subtree] records after transition starts - record[0].removedAnimations length
animation states: pending,pending,pending
animation times: 0,0,0
animation states: pending,pending,pending
animation times: 0,0,0
animation states: pending,pending,pending
animation times: 50000,50000,50000
TEST-UNEXPECTED-FAIL | dom/animation/test/chrome/test_animation_observers.html | [multiple_transitions:subtree] number of running Animations - got 0, expected 3

Compare that to when I run it locally:

TEST-PASS | dom/animation/test/chrome/test_animation_observers.html | [multiple_transitions:subtree] getAnimations().length after transition starts 
animation states: pending,pending,pending
animation times:  0,0,0
TEST-PASS | dom/animation/test/chrome/test_animation_observers.html | [multiple_transitions:subtree] records after transition starts - number of records  
TEST-PASS | dom/animation/test/chrome/test_animation_observers.html | [multiple_transitions:subtree] records after transition starts - record[0].addedAnimations length 
TEST-PASS | dom/animation/test/chrome/test_animation_observers.html | [multiple_transitions:subtree] records after transition starts - record[0].addedAnimations contains expected Animation 
TEST-PASS | dom/animation/test/chrome/test_animation_observers.html | [multiple_transitions:subtree] records after transition starts - record[0].addedAnimations contains expected Animation 
TEST-PASS | dom/animation/test/chrome/test_animation_observers.html | [multiple_transitions:subtree] records after transition starts - record[0].addedAnimations contains expected Animation 
TEST-PASS | dom/animation/test/chrome/test_animation_observers.html | [multiple_transitions:subtree] records after transition starts - record[0].changedAnimations length 
TEST-PASS | dom/animation/test/chrome/test_animation_observers.html | [multiple_transitions:subtree] records after transition starts - record[0].removedAnimations length 
animation states: pending,pending,pending
animation times:  0,0,0
animation states: running,running,running
animation times:  15.104384999999999,15.104384999999999,15.104384999999999
animation states: running,running,running
animation times:  50000,50000,50000
TEST-PASS | dom/animation/test/chrome/test_animation_observers.html | [multiple_transitions:subtree] number of running Animations 

So when we fail, none of the AnimationPlayers actually get to start running for some reason.  When we pass, the first time that the players are running is at least two requestAnimationFrame callbacks after we've tried to start the transitions.  Is that not longer enough?  Should we be, say, waiting for player.ready instead?
(In reply to Cameron McCormack (:heycam) from comment #30)
> So when we fail, none of the AnimationPlayers actually get to start running
> for some reason.  When we pass, the first time that the players are running
> is at least two requestAnimationFrame callbacks after we've tried to start
> the transitions.  Is that not longer enough?  Should we be, say, waiting for
> player.ready instead?

Yes, we should. There are a few reasons why it might take one than one frame for animations to start, paint suppression being one of them.
Attachment #8587042 - Attachment is patch: true
Comment on attachment 8587042 [details] [diff] [review]
wait for animation.ready in tests where we assume the animation has started playing

>@@ -248,16 +251,19 @@ function assert_records(expected, desc) 
>     is(animations.length, 1, "getAnimations().length after transition start");
> 
>     // Wait for the single MutationRecord for the Animation addition to
>     // be delivered.
>     yield await_frame();
>     assert_records([{ added: animations, changed: [], removed: [] }],
>                    "records after transition start");
> 
>+    // Wait for the animation to be playing.
>+    yield animations[0].ready;
>+
>     // Cancel the transition by setting the current animation value.
>     var value = "rgb(128, 255, 0)";
>     is(getComputedStyle(e).backgroundColor, value, "half-way transition value");
>     e.style.backgroundColor = value;

We don't actually have to wait for the animation to get started  in this case since while it is waiting to start it will be frozen at its initial time--i.e. the animation style should still be set. But it doesn't hurt to have this either.

>@@ -279,16 +285,19 @@ function assert_records(expected, desc) 
>     is(animations.length, 1, "getAnimations().length after transition start");
> 
>     // Wait for the single MutationRecord for the Animation addition to
>     // be delivered.
>     yield await_frame();
>     assert_records([{ added: animations, changed: [], removed: [] }],
>                    "records after transition start");
> 
>+    // Wait for the animation to be playing.
>+    yield animations[0].begin;
>+

Probably should be 'ready'.
(And again, it's probably not strictly necessary to wait in this case.)

Actually a bunch of the other cases aren't strictly needed, but they don't hurt. It's most where we're waiting a frame and expecting the animation to be running that we'd be better off waiting on the ready promise. You can still seek an animation while it's waiting to start so most of the tests should work without the extra wait.

r=birtles with begin replaced with ready (and removing any waiting you think is superfluous).
Attachment #8587042 - Flags: review?(bbirtles) → review+
(In reply to Brian Birtles (:birtles) from comment #34)
> Probably should be 'ready'.

Silently not waiting on a promise is a bad failure mode here. :(

> Actually a bunch of the other cases aren't strictly needed, but they don't
> hurt. It's most where we're waiting a frame and expecting the animation to
> be running that we'd be better off waiting on the ready promise. You can
> still seek an animation while it's waiting to start so most of the tests
> should work without the extra wait.

OK.  I'll remove all except those I know are needed.
https://hg.mozilla.org/mozilla-central/rev/a4ac07b1a28b
Status: REOPENED → RESOLVED
Closed: 5 years ago4 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.