Closed Bug 1483526 Opened 6 years ago Closed 6 years ago

Intermittent TEST-UNEXPECTED-TIMEOUT | /html/semantics/embedded-content/media-elements/video_008.htm | expected OK

Categories

(Core :: Audio/Video: Playback, defect, P3)

Product:
Core
Component:
Audio/Video: Playback
Type:
defect

Tracking

()

Status:
RESOLVED WORKSFORME

People

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

References

Details

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

Filed by: nbeleuzu [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=194068974&repo=mozilla-inbound

https://queue.taskcluster.net/v1/task/HeOpqPEwQWeZ4eXXwpoBbQ/runs/0/artifacts/public/logs/live_backing.log

11:37:33     INFO - TEST-START | /html/semantics/embedded-content/media-elements/video_008.htm
11:37:33     INFO - PID 4624 | 1534333053213	Marionette	DEBUG	[4294967430] Frame script loaded
11:37:33     INFO - PID 4624 | 1534333053220	Marionette	DEBUG	[4294967430] Frame script registered
11:37:43     INFO - TEST-UNEXPECTED-TIMEOUT | /html/semantics/embedded-content/media-elements/video_008.htm | expected OK
11:37:43     INFO - TEST-INFO took 10087ms
11:37:43     INFO - PID 4624 | 1534333063274	Marionette	INFO	Stopped listening on port 2828
11:37:43     INFO - PID 4624 | [Child 5104, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
11:37:43     INFO - PID 4624 | [Child 5104, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
11:37:43     INFO - PID 4624 | [Child 4780, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
11:37:43     INFO - PID 4624 | [Child 1360, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
11:37:43     INFO - PID 4624 | [Child 1360, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
11:37:43     INFO - PID 4624 | [Parent 4624, Gecko_IOThread] WARNING: file z:/build/build/src/ipc/chromium/src/base/process_util_win.cc, line 188
11:37:43     INFO - Browser exited with return code 0
11:37:43  WARNING - u'runner_teardown': ()
11:37:43     INFO - Setting up ssl
11:37:43     INFO - certutil | 
11:37:43     INFO - certutil | 
11:37:43     INFO - certutil | 
11:37:43     INFO - Certificate Nickname                                         Trust Attributes
11:37:43     INFO -                                                              SSL,S/MIME,JAR/XPI
11:37:43     INFO - 
11:37:43     INFO - web-platform-tests                                           CT,, 
11:37:43     INFO - 
11:37:43     INFO - Application command: Z:\task_1534331708\build\application\firefox\firefox.exe -marionette about:blank -profile c:\users\task_1534331708\appdata\local\temp\tmpjscjdw.mozrunner
11:37:43     INFO - Starting runner
11:37:45     INFO - PID 4132 | 1534333065224	Marionette	INFO	Listening on port 2828
11:37:45     INFO - PID 4132 | 1534333065655	Marionette	DEBUG	[4294967297] Frame script loaded
11:37:45     INFO - PID 4132 | 1534333065660	Marionette	DEBUG	[4294967297] Frame script registered
11:37:45     INFO - PID 4132 | 1534333065679	Marionette	DEBUG	[4294967297] Received DOM event beforeunload for about:blank
11:37:45     INFO - PID 4132 | 1534333065696	Marionette	DEBUG	[4294967297] Received DOM event pagehide for about:blank
11:37:45     INFO - PID 4132 | 1534333065697	Marionette	DEBUG	[4294967297] Received DOM event unload for about:blank
11:37:45     INFO - PID 4132 | 1534333065702	Marionette	DEBUG	[4294967297] Received DOM event DOMContentLoaded for http://web-platform.test:8000/testharness_runner.html
11:37:45     INFO - PID 4132 | 1534333065729	Marionette	DEBUG	[4294967297] Received DOM event pageshow for http://web-platform.test:8000/testharness_runner.html
11:37:45     INFO - TEST-START | /html/semantics/embedded-content/media-elements/video_loop_base.html
11:37:45     INFO - PID 4132 | 1534333065781	Marionette	DEBUG	[4294967301] Frame script loaded
11:37:45     INFO - PID 4132 | 1534333065790	Marionette	DEBUG	[4294967301] Frame script registered
11:37:45     INFO - PID 4132 | 1534333065898	Marionette	DEBUG	[4294967304] Frame script loaded
11:37:45     INFO - PID 4132 | 1534333065908	Marionette	DEBUG	[4294967304] Frame script registered
11:37:46     INFO - .
11:37:46     INFO - TEST-OK | /html/semantics/embedded-content/media-elements/video_loop_base.html | took 411ms
Component: DOM → Audio/Video
great work Eliza, this is really clear looking.

:heycam, I see you landed these changes 2 days ago in bug 1483121 and bug 1482782, they seem to have caused a high frequency intermittent failure, can you look into fixing this bug?
Blocks: 1482782, 1483121
Flags: needinfo?(jmaher) → needinfo?(cam)
Rank: 29
Priority: -- → P3
I'll take a look.
Assignee: nobody → cam
Status: NEW → ASSIGNED
Flags: needinfo?(cam)
Flags: needinfo?(cam)
That previous one didn't have proper debug info because it was based on a mozilla-inbound build. This one is better:
https://pernos.co/debug/ElebFrbNFZoAjXxKFyVs_g/index.html
I tried debugging this today using the recording in comment 7.  I got as far as the following observations:

* In the failing (timed out) test run, we do correctly call do_play in response to movie_300 starting to play, which does indeed call videotest.done().  This happens about 2 seconds after the start of the test.

* In a local rr recording of a passing test run, the page finishes loading -- at some point shortly after dispatching the play event, we end up removing the document onload blocker, under this stack:

  nsUnblockOnloadEvent::nsUnblockOnloadEvent
  nsIDocument::PostUnblockOnloadEvent
  nsDocument::UnblockOnload
  mozilla::dom::HTMLMediaElement::ChangeDelayLoadStatus
  mozilla::dom::HTMLMediaElement::FirstFrameLoaded
  mozilla::MediaDecoder::FirstFrameLoaded
  ...

and the onload blocker is the last foreground load in the load group.

* In the failing test run, at the time we remove the document onload blocker, there is still one other foreground load active -- for movie_300.  This load is the one started under HTMLMediaElement::LoadFromSourceChildren.

I don't know whether the fact that the document doesn't finish loading affects whether testharness.js thinks the test if finished; I didn't know how to debug what testharness.js was doing from Pernosco, and I didn't try it locally.

I still don't know how the static atom changes I landed affect this test.  My current wild guess is an existing bug in the media loading code somehow became more apparent.

I think it makes sense to pass this over to someone who's more familiar with media loading -- Nils/jya, can you assess this bug and/or find someone to look into it?  Thanks!
Flags: needinfo?(jyavenard)
Flags: needinfo?(drno)
Flags: needinfo?(cam)
:heycam I'm confused... what is the timeout related to? a deadlock?

I don't know how that async_test method works.
Flags: needinfo?(jyavenard)
I don't know what causes the timeout.  The test framework thinks that the test times out, but the call to `videotest.done()` should finish the test.  From the logs I can see that the video is playing.  I don't know whether it does or doesn't make sense that there is a foreground load of the video file, blocking the load event, by the time we call `videotest.done()`, or whether that is actually what is causing the test not to finish, but it is the thing that stood out to me from the logs that differed from a passing test run.
Flags: needinfo?(jyavenard)
Component: Audio/Video → Audio/Video: Playback
Looks like it was a one off. It only occurred on a single day and hasn't reproduced since.
Status: ASSIGNED → RESOLVED
Closed: 6 years ago
Flags: needinfo?(jyavenard)
Resolution: --- → WORKSFORME
Flags: needinfo?(drno)
You need to log in before you can comment on or make changes to this bug.