Intermittent TEST-UNEXPECTED-TIMEOUT | /dom/events/webkit-animation-iteration-event.html | onwebkitanimationiteration event handler should trigger for an animation - Test timed out
Categories
(Core :: DOM: Core & HTML, defect, P3)
Tracking
()
Tracking | Status | |
---|---|---|
firefox74 | --- | fixed |
People
(Reporter: intermittent-bug-filer, Unassigned)
References
(Regression)
Details
(Keywords: intermittent-failure, regression, Whiteboard: , [wptsync upstream][stockwell unknown])
Attachments
(1 file)
Filed by: rmaries [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=284736476&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/e26QhFDHRS-5TNMWQLM0Bw/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/e26QhFDHRS-5TNMWQLM0Bw/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1
[task 2020-01-13T20:51:20.231Z] 20:51:20 INFO - TEST-START | /dom/events/webkit-animation-iteration-event.html
[task 2020-01-13T20:51:20.231Z] 20:51:20 INFO - Run 3/10
[task 2020-01-13T20:51:20.234Z] 20:51:20 INFO - Closing window 29
[task 2020-01-13T20:51:20.357Z] 20:51:20 INFO - PID 6577 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-01-13T20:51:20.398Z] 20:51:20 INFO - PID 6577 | [Child 6839, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /builds/worker/workspace/build/src/layout/base/nsPresContext.cpp, line 848
[task 2020-01-13T20:51:20.616Z] 20:51:20 INFO - PID 6577 | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpREQeYG.mozrunner/runtests_leaks_4702_tab_pid6873.log
[task 2020-01-13T20:51:20.806Z] 20:51:20 INFO - PID 6577 | [Child 6873, Main Thread] WARNING: No CID found when attempting to map contract ID: file /builds/worker/workspace/build/src/xpcom/components/nsComponentManager.cpp, line 721
[task 2020-01-13T20:51:20.868Z] 20:51:20 INFO - PID 6577 | [Parent 6577, Main Thread] WARNING: we only accept nsIURI interface type, patch welcome: file /builds/worker/workspace/build/src/dom/ipc/PropertyBagUtils.cpp, line 112
[task 2020-01-13T20:51:20.871Z] 20:51:20 INFO - PID 6577 | [Child 6839, Main Thread] WARNING: Trying to request nsIHttpChannel from DocumentChannel, this is likely broken: file /builds/worker/workspace/build/src/netwerk/ipc/DocumentChannel.cpp, line 63
[task 2020-01-13T20:51:20.932Z] 20:51:20 INFO - PID 6577 | [Child 6805, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/workspace/build/src/xpcom/base/nsCycleCollector.cpp, line 3362
[task 2020-01-13T20:51:21.042Z] 20:51:21 INFO - PID 6577 | nsStringStats
[task 2020-01-13T20:51:21.043Z] 20:51:21 INFO - PID 6577 | => mAllocCount: 8323
[task 2020-01-13T20:51:21.044Z] 20:51:21 INFO - PID 6577 | => mReallocCount: 0
[task 2020-01-13T20:51:21.045Z] 20:51:21 INFO - PID 6577 | => mFreeCount: 8323
[task 2020-01-13T20:51:21.046Z] 20:51:21 INFO - PID 6577 | => mShareCount: 7343
[task 2020-01-13T20:51:21.047Z] 20:51:21 INFO - PID 6577 | => mAdoptCount: 442
[task 2020-01-13T20:51:21.048Z] 20:51:21 INFO - PID 6577 | => mAdoptFreeCount: 446
[task 2020-01-13T20:51:21.048Z] 20:51:21 INFO - PID 6577 | => Process ID: 6805, Thread ID: 140316871710592
[task 2020-01-13T20:51:21.076Z] 20:51:21 INFO - PID 6577 | Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2020-01-13T20:51:21.274Z] 20:51:21 INFO - PID 6577 | [Child 6873, Main Thread] WARNING: could not set real-time limit at process startup: file /builds/worker/workspace/build/src/dom/ipc/ContentChild.cpp, line 1822
[task 2020-01-13T20:51:51.223Z] 20:51:51 INFO -
[task 2020-01-13T20:51:51.224Z] 20:51:51 INFO - TEST-PASS | /dom/events/webkit-animation-iteration-event.html | onanimationiteration and onwebkitanimationiteration are not aliases
[task 2020-01-13T20:51:51.224Z] 20:51:51 INFO - TEST-PASS | /dom/events/webkit-animation-iteration-event.html | dispatchEvent of a webkitAnimationIteration event does trigger a prefixed event handler or listener
[task 2020-01-13T20:51:51.224Z] 20:51:51 INFO - TEST-PASS | /dom/events/webkit-animation-iteration-event.html | dispatchEvent of a webkitAnimationIteration event does not trigger an unprefixed event handler or listener
[task 2020-01-13T20:51:51.224Z] 20:51:51 INFO - TEST-PASS | /dom/events/webkit-animation-iteration-event.html | dispatchEvent of an animationiteration event does not trigger a prefixed event handler or listener
[task 2020-01-13T20:51:51.225Z] 20:51:51 INFO - TEST-UNEXPECTED-TIMEOUT | /dom/events/webkit-animation-iteration-event.html | onwebkitanimationiteration event handler should trigger for an animation - Test timed out
[task 2020-01-13T20:51:51.225Z] 20:51:51 INFO -
[task 2020-01-13T20:51:51.225Z] 20:51:51 INFO - TEST-UNEXPECTED-NOTRUN | /dom/events/webkit-animation-iteration-event.html | onwebkitanimationiteration event handler should not trigger if an unprefixed event handler also exists - expected PASS
[task 2020-01-13T20:51:51.226Z] 20:51:51 INFO -
[task 2020-01-13T20:51:51.226Z] 20:51:51 INFO - TEST-UNEXPECTED-NOTRUN | /dom/events/webkit-animation-iteration-event.html | onwebkitanimationiteration event handler should not trigger if an unprefixed listener also exists - expected PASS
[task 2020-01-13T20:51:51.226Z] 20:51:51 INFO -
[task 2020-01-13T20:51:51.227Z] 20:51:51 INFO - TEST-UNEXPECTED-NOTRUN | /dom/events/webkit-animation-iteration-event.html | event types for prefixed and unprefixed animationiteration event handlers should be named appropriately - expected PASS
[task 2020-01-13T20:51:51.227Z] 20:51:51 INFO -
[task 2020-01-13T20:51:51.227Z] 20:51:51 INFO - TEST-UNEXPECTED-NOTRUN | /dom/events/webkit-animation-iteration-event.html | webkitAnimationIteration event listener should trigger for an animation - expected PASS
[task 2020-01-13T20:51:51.228Z] 20:51:51 INFO -
[task 2020-01-13T20:51:51.229Z] 20:51:51 INFO - TEST-UNEXPECTED-NOTRUN | /dom/events/webkit-animation-iteration-event.html | webkitAnimationIteration event listener should not trigger if an unprefixed listener also exists - expected PASS
[task 2020-01-13T20:51:51.229Z] 20:51:51 INFO -
[task 2020-01-13T20:51:51.230Z] 20:51:51 INFO - TEST-UNEXPECTED-NOTRUN | /dom/events/webkit-animation-iteration-event.html | webkitAnimationIteration event listener should not trigger if an unprefixed event handler also exists - expected PASS
[task 2020-01-13T20:51:51.231Z] 20:51:51 INFO -
[task 2020-01-13T20:51:51.232Z] 20:51:51 INFO - TEST-UNEXPECTED-NOTRUN | /dom/events/webkit-animation-iteration-event.html | event types for prefixed and unprefixed animationiteration event listeners should be named appropriately - expected PASS
[task 2020-01-13T20:51:51.232Z] 20:51:51 INFO -
[task 2020-01-13T20:51:51.233Z] 20:51:51 INFO - TEST-UNEXPECTED-NOTRUN | /dom/events/webkit-animation-iteration-event.html | webkitAnimationIteration event listener is case sensitive - expected PASS
[task 2020-01-13T20:51:51.234Z] 20:51:51 INFO - TEST-UNEXPECTED-TIMEOUT | /dom/events/webkit-animation-iteration-event.html | expected OK
[task 2020-01-13T20:51:51.234Z] 20:51:51 INFO - TEST-INFO took 30996ms
[task 2020-01-13T20:51:51.264Z] 20:51:51 INFO - PID 6577 | 1578948711257 Marionette INFO Stopped listening on port 34036
[task 2020-01-13T20:51:51.603Z] 20:51:51 INFO - PID 6577 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-01-13T20:51:51.604Z] 20:51:51 INFO - PID 6577 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-01-13T20:51:51.714Z] 20:51:51 INFO - PID 6577 | [2020-01-13T20:51:51Z WARN xulstore::persist] tried to remove key that isn't in the store
[task 2020-01-13T20:51:51.714Z] 20:51:51 INFO - PID 6577 | [2020-01-13T20:51:51Z WARN xulstore::persist] tried to remove key that isn't in the store
[task 2020-01-13T20:51:51.932Z] 20:51:51 INFO - PID 6577 | [Child 6839, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/workspace/build/src/xpcom/base/nsCycleCollector.cpp, line 3362
[task 2020-01-13T20:51:51.968Z] 20:51:51 INFO - PID 6577 | [Child 6646, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/workspace/build/src/xpcom/base/nsCycleCollector.cpp, line 3362
[task 2020-01-13T20:51:51.984Z] 20:51:51 INFO - PID 6577 | nsStringStats
[task 2020-01-13T20:51:51.984Z] 20:51:51 INFO - PID 6577 | => mAllocCount: 8602
[task 2020-01-13T20:51:51.984Z] 20:51:51 INFO - PID 6577 | => mReallocCount: 0
[task 2020-01-13T20:51:51.985Z] 20:51:51 INFO - PID 6577 | => mFreeCount: 8602
[task 2020-01-13T20:51:51.985Z] 20:51:51 INFO - PID 6577 | => mShareCount: 7489
[task 2020-01-13T20:51:51.985Z] 20:51:51 INFO - PID 6577 | => mAdoptCount: 517
[task 2020-01-13T20:51:51.985Z] 20:51:51 INFO - PID 6577 | => mAdoptFreeCount: 521
[task 2020-01-13T20:51:51.986Z] 20:51:51 INFO - PID 6577 | => Process ID: 6839, Thread ID: 140005670995840
[task 2020-01-13T20:51:52.022Z] 20:51:52 INFO - PID 6577 | nsStringStats
[task 2020-01-13T20:51:52.023Z] 20:51:52 INFO - PID 6577 | => mAllocCount: 24511
[task 2020-01-13T20:51:52.024Z] 20:51:52 INFO - PID 6577 | => mReallocCount: 0
[task 2020-01-13T20:51:52.025Z] 20:51:52 INFO - PID 6577 | => mFreeCount: 24511
[task 2020-01-13T20:51:52.025Z] 20:51:52 INFO - PID 6577 | => mShareCount: 11996
[task 2020-01-13T20:51:52.025Z] 20:51:52 INFO - PID 6577 | => mAdoptCount: 450
[task 2020-01-13T20:51:52.027Z] 20:51:52 INFO - PID 6577 | => mAdoptFreeCount: 486
[task 2020-01-13T20:51:52.028Z] 20:51:52 INFO - PID 6577 | => Process ID: 6646, Thread ID: 140380109559680
[task 2020-01-13T20:51:52.044Z] 20:51:52 INFO - PID 6577 | [Child 6672, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/workspace/build/src/xpcom/base/nsCycleCollector.cpp, line 3362
[task 2020-01-13T20:51:52.080Z] 20:51:52 INFO - PID 6577 | nsStringStats
[task 2020-01-13T20:51:52.080Z] 20:51:52 INFO - PID 6577 | => mAllocCount: 13508
[task 2020-01-13T20:51:52.081Z] 20:51:52 INFO - PID 6577 | => mReallocCount: 0
[task 2020-01-13T20:51:52.081Z] 20:51:52 INFO - PID 6577 | => mFreeCount: 13508
[task 2020-01-13T20:51:52.082Z] 20:51:52 INFO - PID 6577 | => mShareCount: 18652
[task 2020-01-13T20:51:52.083Z] 20:51:52 INFO - PID 6577 | => mAdoptCount: 646
[task 2020-01-13T20:51:52.083Z] 20:51:52 INFO - PID 6577 | => mAdoptFreeCount: 656
[task 2020-01-13T20:51:52.084Z] 20:51:52 INFO - PID 6577 | => Process ID: 6672, Thread ID: 140136791775104
[task 2020-01-13T20:51:52.322Z] 20:51:52 INFO - PID 6577 | nsStringStats
[task 2020-01-13T20:51:52.322Z] 20:51:52 INFO - PID 6577 | => mAllocCount: 5796
[task 2020-01-13T20:51:52.323Z] 20:51:52 INFO - PID 6577 | => mReallocCount: 0
[task 2020-01-13T20:51:52.323Z] 20:51:52 INFO - PID 6577 | => mFreeCount: 5796
[task 2020-01-13T20:51:52.323Z] 20:51:52 INFO - PID 6577 | => mShareCount: 2972
[task 2020-01-13T20:51:52.323Z] 20:51:52 INFO - PID 6577 | => mAdoptCount: 72
[task 2020-01-13T20:51:52.323Z] 20:51:52 INFO - PID 6577 | => mAdoptFreeCount: 72
[task 2020-01-13T20:51:52.324Z] 20:51:52 INFO - PID 6577 | => Process ID: 6873, Thread ID: 140013618755456
[task 2020-01-13T20:51:52.581Z] 20:51:52 INFO - PID 6577 | [Parent 6577, Main Thread] WARNING: NS_ENSURE_TRUE(mDB) failed: file /builds/worker/workspace/build/src/netwerk/cache/nsDiskCacheDeviceSQL.cpp, line 1284
[task 2020-01-13T20:51:53.005Z] 20:51:53 INFO - PID 6577 | [Parent 6577, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file /builds/worker/workspace/build/src/js/xpconnect/loader/mozJSComponentLoader.cpp, line 228
[task 2020-01-13T20:51:53.005Z] 20:51:53 INFO - PID 6577 | [Parent 6577, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file /builds/worker/workspace/build/src/js/xpconnect/loader/mozJSComponentLoader.cpp, line 255
[task 2020-01-13T20:51:54.030Z] 20:51:54 INFO - PID 6577 | nsStringStats
[task 2020-01-13T20:51:54.030Z] 20:51:54 INFO - PID 6577 | => mAllocCount: 137201
[task 2020-01-13T20:51:54.030Z] 20:51:54 INFO - PID 6577 | => mReallocCount: 0
[task 2020-01-13T20:51:54.030Z] 20:51:54 INFO - PID 6577 | => mFreeCount: 137201
[task 2020-01-13T20:51:54.031Z] 20:51:54 INFO - PID 6577 | => mShareCount: 118070
[task 2020-01-13T20:51:54.031Z] 20:51:54 INFO - PID 6577 | => mAdoptCount: 2615
[task 2020-01-13T20:51:54.033Z] 20:51:54 INFO - PID 6577 | => mAdoptFreeCount: 2733
[task 2020-01-13T20:51:54.033Z] 20:51:54 INFO - PID 6577 | => Process ID: 6577, Thread ID: 139875400021888
[task 2020-01-13T20:51:54.042Z] 20:51:54 INFO - Browser exited with return code 0
Comment 1•5 years ago
|
||
Boris, https://bugzilla.mozilla.org/show_bug.cgi?id=1607918#c5 seems to be the culprit. Could you take a look?
Updated•5 years ago
|
Updated•5 years ago
|
Updated•5 years ago
|
![]() |
||
Comment 2•5 years ago
|
||
Hmm. I've been trying to reproduce this locally without any luck, so far. Any chance of trying to get an rr or pernosco recording of one of these failures?
Emilio, does anything in the test jump out at you as likely to time out (e.g. due to not running the animation)? Or any ideas who would be good to ping on that? In particular, I'm not sure about the tests' waiting for requestAnimationFrame bits and whether those are correct...
Comment hidden (Intermittent Failures Robot) |
Comment 4•5 years ago
|
||
waitForEventThenAnimationFrame
is a bit fishy in the sense that it's not local to the test (it adds the event listener to the window object rather than the div
the test is concerned about)... So given that promise_test
s run concurrently it seems it could make some of the tests flaky. But I would expect the test to be flaky in the "test intermittently fails" way, not in the "test intermittently doesn't run" way.
I don't get the requestAnimationFrame
wait that that is doing, I don't think it should be needed. You've received the event anyway by the time you call requestAnimationFrame
, right?
Another thing that looks fishy to me is that the test is combining prefixed and unprefixed handlers in tests that run concurrently, and that whether we dispatch the legacy one depends on whether we have listeners for the non-legacy one, if I understood this check correctly... But again (and I haven't looked so deeply into it), that should make us fail some tests, not time out, probably...
Oh! But waitForEventThenAnimationFrame(t, unprefixedHandler);
overrides the window's onanimationfoo
handler, right? So if two of these run concurrently one of the promises won't resolve... Or if the cleanup function of a test runs before the event the other test is waiting is dispatched. That sounds like it could cause these timeouts, and I think they're bugs in the test.
![]() |
||
Comment 5•5 years ago
|
||
So given that promise_tests run concurrently
Do they? They run async, but I thought they guaranteed running in order, with each test chained to the then
of the previous test?
Comment hidden (Intermittent Failures Robot) |
![]() |
||
Comment 8•5 years ago
|
||
I wonder whether waiting one animation frame tick after the rule insertions at https://searchfox.org/mozilla-central/rev/e878e5b81bb319c141900ce9cfcde732df5c8449/testing/web-platform/tests/dom/events/resources/prefixed-animation-event-tests.js#26-34 would help... As in, is it possible that we're trying to trigger transitions/animations before those rules have had a chance to take effect?
![]() |
||
Comment 9•5 years ago
|
||
https://github.com/web-platform-tests/wpt/pull/19099#issuecomment-577375311 has some possibly-relevant info. Will do some try runs.
Comment 10•5 years ago
|
||
(In reply to Boris Zbarsky [:bzbarsky, bz on IRC] from comment #8)
I wonder whether waiting one animation frame tick after the rule insertions at https://searchfox.org/mozilla-central/rev/e878e5b81bb319c141900ce9cfcde732df5c8449/testing/web-platform/tests/dom/events/resources/prefixed-animation-event-tests.js#26-34 would help... As in, is it possible that we're trying to trigger transitions/animations before those rules have had a chance to take effect?
I don't think that can be true. The div
element does have its style flushed before getting added to the DOM so it should always fire the transition. Triggering the animation doesn't depend on the previous style, so we should trigger it regardless.
(In reply to Boris Zbarsky [:bzbarsky, bz on IRC] from comment #9)
https://github.com/web-platform-tests/wpt/pull/19099#issuecomment-577375311 has some possibly-relevant info. Will do some try runs.
Ah, d'oh, I didn't think we wouldn't fire the animation iteration events... That'd make sense.
Updated•5 years ago
|
Comment hidden (Intermittent Failures Robot) |
![]() |
||
Comment 12•5 years ago
|
||
This just got fixed upstream: https://github.com/web-platform-tests/wpt/pull/21441
We can probably cherry-pick that so we don't have to wait for it to be downstreamed....
![]() |
||
Comment 13•5 years ago
|
||
Some CI systems are very slow, so end up skipping short animations and
not firing iteration events for them. This commit changes
webkit-animation-iteration-event.html to have a very long iteration
duration, but uses a negative delay to position the start point right
before the end of the first iteration.
This is a cherry-pick of
https://github.com/web-platform-tests/wpt/commit/fdc1a89a01a437cce2afa78fad440f68d1d46935
and was reviewed upstream.
Comment 14•5 years ago
|
||
Comment 15•5 years ago
|
||
bugherder |
Comment hidden (Intermittent Failures Robot) |
Description
•