Closed Bug 1608980 Opened 5 years ago Closed 5 years ago

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)

Product:
Core
Component:
DOM: Core & HTML
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla74
Tracking Flags:
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)

Bug 1608980. Use long animation in webkit-animation-iteration-event.html
47 bytes, text/x-phabricator-request
Details | Review

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

Boris, https://bugzilla.mozilla.org/show_bug.cgi?id=1607918#c5 seems to be the culprit. Could you take a look?

Flags: needinfo?(bzbarsky)
Regressed by: 1607918
Has Regression Range: --- → yes
Keywords: regression
Summary: Intermittent TVw TEST-UNEXPECTED-TIMEOUT | /dom/events/webkit-animation-iteration-event.html | onwebkitanimationiteration event handler should trigger for an animation - Test timed out → Intermittent TEST-UNEXPECTED-TIMEOUT | /dom/events/webkit-animation-iteration-event.html | onwebkitanimationiteration event handler should trigger for an animation - Test timed out
See Also: → 1609834

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

Flags: needinfo?(emilio)

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

Flags: needinfo?(emilio)

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?

Ah you're right... I was looking at the wrong promise_test :(

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?

Flags: needinfo?(bzbarsky) → needinfo?(emilio)
See Also: → 1609762
See Also: → 1610703

https://github.com/web-platform-tests/wpt/pull/19099#issuecomment-577375311 has some possibly-relevant info. Will do some try runs.

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

Flags: needinfo?(emilio)
Priority: -- → P3

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

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.

Pushed by bzbarsky@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/21f55b52f6d5 Use long animation in webkit-animation-iteration-event.html
Whiteboard: [stockwell needswork:owner] → [stockwell needswork:owner], [wptsync upstream]

https://hg.mozilla.org/mozilla-central/rev/21f55b52f6d5

Status: NEW → RESOLVED
Closed: 5 years ago
status-firefox74: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla74
See Also: → 1623194
See Also: → 1651316
See Also: → 1671068
See Also: → 1677370
See Also: → 1688119
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: