Closed Bug 1090523 Opened 10 years ago Closed 9 years ago

Intermittent test_eme_canvas_blocked.html | Test timed out.

Categories

(Core :: Audio/Video, defect, P2)

Product:
Core
Component:
Audio/Video
Platform:
x86
Windows 7
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla36
Tracking Flags:
Tracking Status
firefox34 --- unaffected
firefox35 --- unaffected
firefox36 --- fixed
firefox37 --- affected
firefox38 --- affected
firefox39 --- affected
firefox-esr31 --- unaffected

People

(Reporter: RyanVM, Assigned: eflores)

References

(Blocks 1 open bug)

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

Patch: Even more EME test logging
14.68 KB, patch
eflores
: review+
Details | Diff | Splinter Review 
https://treeherder.mozilla.org/ui/logviewer.html#?job_id=3364884&repo=mozilla-inbound

builder 	Windows 7 32-bit mozilla-inbound opt test mochitest-2
buildid 	20141028083451
builduid 	12557eaff6324553b2ae25d48cba2a5f
results 	warnings (1)
revision 	f9fd1dde27c5
slave 		t-w732-ix-031
starttime 	Tue Oct 28 2014 12:45:50 GMT-0400 (Eastern Standard Time)

09:59:35 INFO - 2169 INFO TEST-START | /tests/dom/media/test/test_eme_canvas_blocked.html
09:59:35 INFO - I/SampleTable( 616): There are reordered frames present.
09:59:35 INFO - E/MPEG4Extractor( 616): No width or height, assuming worst case 1080p
09:59:35 INFO - W/MPEG4Extractor( 616): deferring processing of saiz box
09:59:35 INFO - W/MPEG4Extractor( 616): deferring processing of saio box
09:59:35 INFO - W/MPEG4Extractor( 616): deferring processing of saiz box
09:59:35 INFO - W/MPEG4Extractor( 616): deferring processing of saio box
10:05:02 INFO - TEST-INFO | screenshot: exit status 0
10:05:02 INFO - 2170 INFO Started Tue Oct 28 2014 09:59:35 GMT-0700 (Pacific Standard Time) (1414515575.38s)
10:05:02 INFO - 2171 INFO TEST-PASS | /tests/dom/media/test/test_eme_canvas_blocked.html | [started short-cenc.mp4-0] Length of array should match number of running tests
10:05:02 INFO - 2172 INFO TEST-PASS | /tests/dom/media/test/test_eme_canvas_blocked.html | [started gizmo-frag-cencinit.mp4-1] Length of array should match number of running tests
10:05:02 INFO - 2173 INFO fetching resource gizmo-frag-cencinit.mp4
10:05:02 INFO - 2174 INFO short-cenc.mp4-0 got encrypted event
10:05:02 INFO - 2175 INFO fetching resource gizmo-frag-cenc1.m4s
10:05:02 INFO - 2176 INFO gizmo-frag-cencinit.mp4-1 got encrypted event
10:05:02 INFO - 2177 INFO short-cenc.mp4-0 created MediaKeys object ok
10:05:02 INFO - 2178 INFO short-cenc.mp4-0 set MediaKeys on <video> element ok
10:05:02 INFO - 2179 INFO gizmo-frag-cencinit.mp4-1 created MediaKeys object ok
10:05:02 INFO - 2180 INFO gizmo-frag-cencinit.mp4-1 set MediaKeys on <video> element ok
10:05:02 INFO - 2181 INFO got message from CDM: { "kids":["flcdAX5XHQF-Vx0BflcdAQ","flcdAn5XHQJ-Vx0CflcdAg"], "type":"temporary"}
10:05:02 INFO - 2182 INFO TEST-PASS | /tests/dom/media/test/test_eme_canvas_blocked.html | Key session type should match
10:05:02 INFO - 2183 INFO TEST-PASS | /tests/dom/media/test/test_eme_canvas_blocked.html | message event should contain key ID array
10:05:02 INFO - 2184 INFO found key 7e5711117e5711117e5711117e571111 for key id 7e571d017e571d017e571d017e571d01
10:05:02 INFO - 2185 INFO found key 7e5722227e5722227e5722227e572222 for key id 7e571d027e571d027e571d027e571d02
10:05:02 INFO - 2186 INFO sending update message to CDM: {"keys":[{"kty":"oct","alg":"A128KW","kid":"flcdAX5XHQF-Vx0BflcdAQ","k":"flcREX5XERF-VxERflcREQ"},{"kty":"oct","alg":"A128KW","kid":"flcdAn5XHQJ-Vx0CflcdAg","k":"flciIn5XIiJ-VyIiflciIg"}],"type":"temporary"}
10:05:02 INFO - 2187 INFO got message from CDM: { "kids":["flcdA35XHQN-Vx0DflcdAw","flcdBH5XHQR-Vx0EflcdBA"], "type":"temporary"}
10:05:02 INFO - 2188 INFO TEST-PASS | /tests/dom/media/test/test_eme_canvas_blocked.html | Key session type should match
10:05:02 INFO - 2189 INFO TEST-PASS | /tests/dom/media/test/test_eme_canvas_blocked.html | message event should contain key ID array
10:05:02 INFO - 2190 INFO found key 7e5733337e5733337e5733337e573333 for key id 7e571d037e571d037e571d037e571d03
10:05:02 INFO - 2191 INFO found key 7e5744447e5744447e5744447e574444 for key id 7e571d047e571d047e571d047e571d04
10:05:02 INFO - 2192 INFO sending update message to CDM: {"keys":[{"kty":"oct","alg":"A128KW","kid":"flcdA35XHQN-Vx0DflcdAw","k":"flczM35XMzN-VzMzflczMw"},{"kty":"oct","alg":"A128KW","kid":"flcdBH5XHQR-Vx0EflcdBA","k":"fldERH5XRER-V0REfldERA"}],"type":"temporary"}
10:05:02 INFO - 2193 INFO MediaKeySession update ok!
10:05:02 INFO - 2194 INFO MediaKeySession update ok!
10:05:02 INFO - 2195 INFO fetching resource gizmo-frag-cenc2.m4s
10:05:02 INFO - 2196 INFO TEST-PASS | /tests/dom/media/test/test_eme_canvas_blocked.html | short-cenc.mp4-0 - Should throw an error when trying to draw EME video to canvas.
10:05:02 INFO - 2197 INFO [finished short-cenc.mp4-0] remaining= gizmo-frag-cencinit.mp4-1
10:05:02 INFO - 2198 INFO TEST-PASS | /tests/dom/media/test/test_eme_canvas_blocked.html | [finished short-cenc.mp4-0] Length of array should match number of running tests
10:05:02 INFO - 2199 INFO Watchdog remaining tests= gizmo-frag-cencinit.mp4-1
10:05:02 INFO - 2200 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/test/test_eme_canvas_blocked.html | Test timed out. - expected PASS
10:05:03 INFO - 2201 INFO TEST-OK | /tests/dom/media/test/test_eme_canvas_blocked.html | took 328349ms
Flags: needinfo?(cpearce)
Bug 1071482 backed out.
Assignee: nobody → cpearce
Status: NEW → RESOLVED
Closed: 10 years ago
status-firefox34: --- → unaffected
status-firefox35: --- → unaffected
status-firefox36: --- → fixed
status-firefox-esr31: --- → unaffected
Flags: needinfo?(cpearce)
Resolution: --- → FIXED
Target Milestone: --- → mozilla36
(In reply to Ryan VanderMeulen [:RyanVM UTC-4] from comment #5)
> Bug 1071482 backed out.

and re-landed and happened again :( 

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

Chris, could you take a look, thanks!
Status: RESOLVED → REOPENED
Flags: needinfo?(cpearce)
Resolution: FIXED → ---
Yes.
Flags: needinfo?(cpearce)
Based on the new logging I added when I landed, the MSE resource is not reaching loadedmetadata state. We appear to be correctly downloading the segments. It's strange however that the timestamps on the logs are incorrect when a timeout happens.

I will add more logging to ensure that we're appending data into the MSE stream correctly.
Even more logging, to help diagnose intermittent failure here.
Attachment #8516419 - Flags: review?(edwin)
Attachment #8516419 - Flags: review?(edwin) → review+
Debugging this on linux has so far led me to MediaPromises in MP4Reader. It seems that when MP4Reader tries to resolve a promise with MediaData (both audio and video) too early, it is not handled anywhere. I have seen this for both the first video frame and first audio frame. Second frame and onwards usually work, but this means the first frame is lost and the MediaDecoderStateMachine gets stuck in DECODING_FIRST_FRAME.

If it happens only to audio it works because the media element proceeds to HAVE_METADATA, HAVE_CURRENT_DATA as usual.
If it happens to video pre-bug 879717 it works because the media element will proceed to HAVE_CURRENT_DATA and beyond even without a video frame.
If it happens to video after bug 879717 it won't work because the media element will hold its readystate at HAVE_METADATA (and the events "loadeddata", "canplay", "playing", etc.) until a video frame gets shown (per the spec).

Too much logging will make it go away though so it's a hard thing to trace.
Depends on: 1121342
Depends on: 1121750
No longer blocks: 879717
Blocks: EME
Assignee: cpearce → edwin
Flags: needinfo?(edwin)
Chris, Edwin: does this intermittent test failure need to block our EME MVP with Adobe?
Flags: needinfo?(cpearce)
I think it should.
Flags: needinfo?(cpearce)
RyanVM says this test is near permafail, not intermittent. We should investigate this failure before he disables the test.
Mass update firefox-status to track EME uplift.
status-firefox37: --- → fixed
status-firefox38: --- → fixed
status-firefox39: --- → fixed
Depends on: 1140675
Clearing ni?. See bug 1140675.
Flags: needinfo?(edwin)
This test failure just changed a general timeout to `ValueError: invalid literal for int() with base 10: 'ps:'` yesterday (comment 198). Did something change in the test runner or on the test machines?
That's bug 1145364. Unrelated to this issue.
Edwin, will you be able to work on this EME test failure soon? Can we disable this test in the meantime? These test failures make the sheriffs' work harder and generate a lot of bugmail.
Flags: needinfo?(edwin)
Priority: -- → P1
Priority: P1 → P2
I declare victory. I think this was fixed by bug 1154133.
Status: REOPENED → RESOLVED
Closed: 10 years ago → 9 years ago
Flags: needinfo?(edwin)
Keywords: leave-open
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: