Filed by: apavel [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=324654695&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/LnJl6fr-QCG6pI3RjP8pQQ/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/LnJl6fr-QCG6pI3RjP8pQQ/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

[task 2020-12-16T06:20:55.537Z] 06:20:55     INFO - TEST-START | toolkit/content/tests/widgets/test_videocontrols_focus.html
[task 2020-12-16T06:20:55.559Z] 06:20:55     INFO - GECKO(7488) | [Parent 7496, Main Thread] WARNING: Failed to retarget HTML data delivery to the parser thread.: file /builds/worker/checkouts/gecko/parser/html/nsHtml5StreamParser.cpp:1180
[task 2020-12-16T06:20:55.707Z] 06:20:55     INFO - GECKO(7488) | [Parent 7496, MediaSupervisor #1] WARNING: Checking version is only allowed only from the content process.: file /builds/worker/checkouts/gecko/dom/media/mediacapabilities/DecoderBenchmark.cpp:215
[task 2020-12-16T06:20:55.717Z] 06:20:55     INFO - GECKO(7488) | [Parent 7496, MediaSupervisor #1] WARNING: Checking version is only allowed only from the content process.: file /builds/worker/checkouts/gecko/dom/media/mediacapabilities/DecoderBenchmark.cpp:215
[task 2020-12-16T06:20:56.546Z] 06:20:56     INFO - TEST-INFO | started process screenshot
[task 2020-12-16T06:20:56.616Z] 06:20:56     INFO - TEST-INFO | screenshot: exit 0
[task 2020-12-16T06:20:56.616Z] 06:20:56     INFO - Buffered messages logged at 06:20:55
[task 2020-12-16T06:20:56.617Z] 06:20:56     INFO - add_task | Entering test setup
[task 2020-12-16T06:20:56.618Z] 06:20:56     INFO - Waiting for video to load
[task 2020-12-16T06:20:56.618Z] 06:20:56     INFO - Playing video
[task 2020-12-16T06:20:56.618Z] 06:20:56     INFO - Waiting for controls to hide
[task 2020-12-16T06:20:56.618Z] 06:20:56     INFO - add_task | Leaving test setup
[task 2020-12-16T06:20:56.618Z] 06:20:56     INFO - add_task | Entering test testShowControlsOnFocus
[task 2020-12-16T06:20:56.618Z] 06:20:56     INFO - TEST-PASS | toolkit/content/tests/widgets/test_videocontrols_focus.html | Controls initially hidden 
[task 2020-12-16T06:20:56.618Z] 06:20:56     INFO - Focusing play button
[task 2020-12-16T06:20:56.618Z] 06:20:56     INFO - Buffered messages finished
[task 2020-12-16T06:20:56.618Z] 06:20:56     INFO - TEST-UNEXPECTED-FAIL | toolkit/content/tests/widgets/test_videocontrols_focus.html | Controls shown after focus 
[task 2020-12-16T06:20:56.618Z] 06:20:56     INFO - SimpleTest.ok@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:417:16
[task 2020-12-16T06:20:56.618Z] 06:20:56     INFO - testShowControlsOnFocus@chrome://mochitests/content/chrome/toolkit/content/tests/widgets/test_videocontrols_focus.html:76:5
[task 2020-12-16T06:20:56.619Z] 06:20:56     INFO - GECKO(7488) | [Parent 7496, Main Thread] WARNING: Wrong inner/outer window combination!: file /builds/worker/checkouts/gecko/dom/base/Document.cpp:7321
[task 2020-12-16T06:20:56.771Z] 06:20:56     INFO - TEST-PASS | toolkit/content/tests/widgets/test_videocontrols_focus.html | Controls hidden after timeout 
[task 2020-12-16T06:20:56.771Z] 06:20:56     INFO - add_task | Leaving test testShowControlsOnFocus
[task 2020-12-16T06:20:56.790Z] 06:20:56     INFO - GECKO(7488) | MEMORY STAT | vsize 2104278MB | vsizeMaxContiguous 65439269MB | residentFast 317MB | heapAllocated 118MB
[task 2020-12-16T06:20:56.810Z] 06:20:56     INFO - TEST-OK | toolkit/content/tests/widgets/test_videocontrols_focus.html | took 1274ms
[task 2020-12-16T06:20:56.839Z] 06:20:56     INFO - GECKO(7488) | [Parent 7496, Main Thread] WARNING: Failed to retarget HTML data delivery to the parser thread.: file /builds/worker/checkouts/gecko/parser/html/nsHtml5StreamParser.cpp:1180```

Tier1 failure log: https://treeherder.mozilla.org/logviewer?job_id=324690925&repo=autoland&lineNumber=14261

Jamie, please take a look.

I can't reproduce this locally. However, if I run all tests with --verify, I do get a timeout when waiting for the controls to hide after focusing the play button. Debugging suggests this is caused by rogue mousein/mouseout events firing while my test is running... but they're definitely not fired by my test.

Gijs, any idea how we could get rogue mouse events during a --headless --verify test run that aren't generated by the test itself?

Set release status flags based on info from the regressing bug 494175

I've been repro'ing locally with a macOS artifact debug build, but, between my pile of meetings today, haven't yet gotten to the bottom of what's going on here (so keeping needinfo)

But broadly, it would seem that when the test fails, we focus a button inside the controls, we get a focusin event immediately, which means we start fading in the control bar as an animation, which then (somehow) takes N milliseconds, where N is approximately equal to the hide control timeout, so that as we finish the animation and fire a controlbarchange event, we then immediately start hiding it again. At that point, because the video control code overrides the hidden property getter to also check for the fadeout class, and because we add that class when we start hiding the controls again, the test fails.

I've tried overwriting the controlbar animation duration at https://searchfox.org/mozilla-central/rev/8d722de75886d6bffc116772a1db8854e34ee6a7/toolkit/content/widgets/videocontrols.js#1494 with 10ms, but that doesn't appear to make a difference, and I don't understand why - it almost seems as if we're attempting to start an animation but then don't (for some reason) and then resolve the animation finished promise when the hiding timeout goes off, or something.

(In reply to :Gijs (he/him) from comment #6)

I've been repro'ing locally with a macOS artifact debug build

Ah, I hadn't tried this with a debug build yet. That probably would've made sense, but I need to clobber, and ... things.

But broadly, it would seem that when the test fails, we focus a button inside the controls, we get a focusin event immediately, which means we start fading in the control bar as an animation, which then (somehow) takes N milliseconds, where N is approximately equal to the hide control timeout

The videocontrols code does have a comment mentioning an animation delay of 750ms and animation duration of 300ms:
https://searchfox.org/mozilla-central/rev/8d722de75886d6bffc116772a1db8854e34ee6a7/toolkit/content/widgets/videocontrols.js#673
This was related to the throbber, but I wondered whether part of it was more general than that? (As an aside, I couldn't find any 300 value anywhere in the code, so maybe this comment is wrong?)

This is one reason I was reluctant to mess with the hide timeout. I wonder if this goes away if we just stop messing with the hide timeout?

I've tried overwriting the controlbar animation duration at https://searchfox.org/mozilla-central/rev/8d722de75886d6bffc116772a1db8854e34ee6a7/toolkit/content/widgets/videocontrols.js#1494 with 10ms, but that doesn't appear to make a difference, and I don't understand why - it almost seems as if we're attempting to start an animation but then don't (for some reason) and then resolve the animation finished promise when the hiding timeout goes off, or something.

Is it possible you were seeing rogue mousein/mouseout events like I was elsewhere? That only happened for me with --verify running multiple tests, though. That certainly messes with things.

(In reply to James Teh [:Jamie] from comment #7)

The videocontrols code does have a comment mentioning an animation delay of 750ms and animation duration of 300ms:
https://searchfox.org/mozilla-central/rev/8d722de75886d6bffc116772a1db8854e34ee6a7/toolkit/content/widgets/videocontrols.js#673
This was related to the throbber, but I wondered whether part of it was more general than that? (As an aside, I couldn't find any 300 value anywhere in the code, so maybe this comment is wrong?)

I think the comment is outdated. The animations, AFAICT, are all defined in the JS.

This is one reason I was reluctant to mess with the hide timeout. I wonder if this goes away if we just stop messing with the hide timeout?

Seems to locally. I'll put up the patch - please land if you think it looks good, as I'm about to pumpkin for the night.

https://hg.mozilla.org/mozilla-central/rev/77d4473410e3

This is still happening.

Recent failure: https://treeherder.mozilla.org/logviewer?job_id=325756026&repo=autoland&lineNumber=130125

(In reply to Bogdan Tara[:bogdan_tara | bogdant] from comment #13)

This is still happening.

Recent failure: https://treeherder.mozilla.org/logviewer?job_id=325756026&repo=autoland&lineNumber=130125

Please file a new bug and check if something regressed this - the frequency was sufficiently high before (and it went away completely in the week leading up to Christmas, despite plenty of pushes then) that this is either much lower frequency now or something new has tripped a similar issue. Either way we should treat it as a separate issue.

Done, thank you.