Closed Bug 1186556 Opened 10 years ago Closed 10 years ago

Intermittent test_eme_playback.html,test_eme_stream_capture_blocked_case1.html | Test timed out | called finish() multiple times

Categories

(Core :: Audio/Video, defect)

Product:
Core
Component:
Audio/Video
Platform:
ARM
Gonk (Firefox OS)
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla42
Tracking Flags:
Tracking Status
firefox40 --- unaffected
firefox41 --- unaffected
firefox42 --- fixed
firefox-esr38 --- unaffected

People

(Reporter: RyanVM, Assigned: jya)

References

Details

(Keywords: intermittent-failure)

10:12:32 INFO - 261 INFO TEST-PASS | dom/media/test/test_eme_playback.html | [17:12:17.594] 640x360 then 640x480-18 key with id 7e571d037e571d037e571d037e571d11 was usable as expected 10:12:32 INFO - 262 INFO TEST-PASS | dom/media/test/test_eme_playback.html | [17:12:17.612] 640x360 then 640x480-18 key with id 7e571d047e571d047e571d047e571d21 was usable as expected 10:12:32 INFO - 263 INFO TEST-PASS | dom/media/test/test_eme_playback.html | [17:12:17.632] 640x360 then 640x480-18 key with id 7e571d037e571d037e571d037e571d12 was usable as expected 10:12:32 INFO - 264 INFO [finished 640x360 then 640x480-18] remaining= 10:12:32 INFO - 265 INFO TEST-PASS | dom/media/test/test_eme_playback.html | [finished 640x360 then 640x480-18] Length of array should match number of running tests 10:12:32 INFO - 266 INFO [17:12:30.770] video-only with 2 keys-0 loadstart 10:12:32 INFO - 267 INFO [17:12:30.828] video-only with 2 keys-0 error 10:12:32 INFO - 268 INFO [17:12:30.863] audio&video tracks, both with all keys-2 loadstart 10:12:32 INFO - 269 INFO [17:12:30.997] audio&video tracks, both with all keys-2 error 10:12:32 INFO - 270 INFO [17:12:31.70] 400x300 audio&video tracks, each with its key-4 loadstart 10:12:32 INFO - 271 INFO [17:12:31.122] 400x300 audio&video tracks, each with its key-4 error 10:12:32 INFO - 272 INFO [17:12:31.170] 640x480@959kbps audio&video tracks, each with its key-6 loadstart 10:12:32 INFO - 273 INFO [17:12:31.332] 640x480@959kbps audio&video tracks, each with its key-6 error 10:12:32 INFO - 274 INFO [17:12:31.364] 640x480 then 400x300, same key (2nd) per track-8 loadstart 10:12:32 INFO - 275 INFO [17:12:31.418] 640x480 then 400x300, same key (2nd) per track-8 error 10:12:32 INFO - 276 INFO [17:12:31.487] 400x300 with 1st keys then 640x480 with 2nd keys-10 loadstart 10:12:32 INFO - 277 INFO [17:12:31.683] 400x300 with 1st keys then 640x480 with 2nd keys-10 error 10:12:32 INFO - 278 INFO [17:12:31.718] 640x480@624kbps with 1st keys then 640x480@959kbps with 2nd keys-12 loadstart 10:12:32 INFO - 279 INFO [17:12:31.750] 640x480@624kbps with 1st keys then 640x480@959kbps with 2nd keys-12 error 10:12:32 INFO - 280 INFO [17:12:31.771] 400x300 as-is then 400x300 presented as 533x300-14 loadstart 10:12:32 INFO - 281 INFO [17:12:31.799] 400x300 as-is then 400x300 presented as 533x300-14 error 10:12:32 INFO - 282 INFO [17:12:31.829] 640x360-16 loadstart 10:12:32 INFO - 283 INFO [17:12:31.855] 640x360-16 error 10:12:32 INFO - 284 INFO [17:12:31.882] 640x360 then 640x480-18 loadstart 10:12:32 INFO - 285 INFO [17:12:31.907] 640x360 then 640x480-18 error 10:12:32 INFO - 286 INFO TEST-UNEXPECTED-FAIL | dom/media/test/test_eme_playback.html | Test timed out. 10:12:32 INFO - reportError@SimpleTest/TestRunner.js:334:7 10:12:32 INFO - TestRunner._checkForHangs@SimpleTest/TestRunner.js:354:7 10:12:38 INFO - 287 INFO Finished at Wed Jul 22 2015 17:12:38 GMT+0000 (UTC) (1437585158.531s) 10:12:38 INFO - 288 INFO Running time: 424.75s 10:12:38 INFO - MEMORY STAT | vsize 180MB | residentFast 77MB | heapAllocated 27MB 10:12:39 INFO - 289 ERROR [SimpleTest.finish()] this test already called finish! 10:12:39 INFO - 290 INFO TEST-UNEXPECTED-ERROR | dom/media/test/test_eme_playback.html | called finish() multiple times 10:12:39 INFO - TEST-INFO took 433956ms 10:12:40 INFO - 291 INFO TEST-OK | dom/media/test/test_eme_playback.html
Forgetting about the timeout, we have the finish called multiple times.
Flags: needinfo?(gsquelart)
The "called finish() multiple times" issue is probably because of the bail function in eme.js. 'bail' is used in multiple places across EME tests, as a 'video.onerror' handler and in other situations. So if an error occurs, a message is printed and SimpleTest.finish() is called; but the mochitest code itself may not actually notice the failure and will continue running, potentially producing more errors and/or calling a normal end-of-test finish(). The best solution is not to fail! In this case the test would run its course and call finish() once at the end. Otherwise to prevent this issue we would need to modify all tests to ensure that finish() is only ever called once (either by having a proxy function that only calls finish() the first time; or by ensuring that the test actually stops running); But this would not address the actual cause(s) of failures, e.g. whatever caused a timeout in the first instance. It might still be worth fixing the multiple finish() symptoms, to at least remove the distraction; I'll spawn a separate bug for that. I think this bug here should be focused on the timeout problem.
Flags: needinfo?(gsquelart)
test_eme_stream_capture_blocked_case1.html immediately after test_eme_playback.html is also seeing this now. Interestingly, chunking boundaries have changed since this bug got filed and test_eme_stream_capture_blocked_case1.html is now the first test in the mochitest-15 chunk.
Summary: Intermittent test_eme_playback.html | Test timed out | called finish() multiple times → Intermittent test_eme_playback.html,test_eme_stream_capture_blocked_case1.html | Test timed out | called finish() multiple times
jya: seems this is pretty frequent now, is there any fix or so insight ?
Flags: needinfo?(jyavenard)
not at this stage. We've been swamped getting MSE ready for 42 ; that eme failures have been largely ignored :(
Flags: needinfo?(jyavenard)
Finally had a look: You can see in the log: "Tracks loaded" Which in eme.js will only occurs if: if (loadParams && loadParams.noEndOfStream) { Log(token, "Tracks loaded"); } else { Log(token, "Tracks loaded, calling MediaSource.endOfStream()"); ms.endOfStream(); } So that means we have loadParams.noEndOfStream set to true ; so mediaSource.endOfStream() will never ever be called. There's no guarantee any frames will come out of the decoder until a keyframe is found ; and the windows decoder is known to suck in outputting frames until its drained (bug 1191138). the attribute noEndOfStream is never set anywhere. It's no wonder all the eme tests fail with intermittent failures.
correction, noEndOfStream *is* set; but it's explicitly set to true, which is wrong. To test the theory: here is one test try where decoders aren't flushed purposefully in waiting mode. https://treeherder.mozilla.org/#/jobs?repo=try&revision=bb9fb8000cdc note that all test_eme_*.html are consistently failing in windows 8.. This is with noEndOfStream set to false: https://treeherder.mozilla.org/#/jobs?repo=try&revision=1875d7c4cffe
https://treeherder.mozilla.org/#/jobs?repo=try&revision=0377dce97566 didn't happen a single time in over 300 runs. Going to push it on as a=testonly test_eme_playback.html is a different problem ; should be separated from this bug I think
Flags: needinfo?(ryanvm)
Still happened once on B2G: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=12660384 The other ones were results from before the push. I thought MSE on B2G was disabled in testing as there's no working decoder. Alfredo, should we disable the test_eme_* on B2G? It doesn't make sense to have them active if MSE tests are disabled
Flags: needinfo?(ayang)
(In reply to Jean-Yves Avenard [:jya] from comment #391) > Still happened once on B2G: > https://treeherder.mozilla.org/logviewer.html#?repo=mozilla- > inbound&job_id=12660384 > > The other ones were results from before the push. > > I thought MSE on B2G was disabled in testing as there's no working decoder. > > Alfredo, should we disable the test_eme_* on B2G? It doesn't make sense to > have them active if MSE tests are disabled test_eme_* uses BlankDecoderModule on b2g, although it's not for MSE but I think it may help for EME part. What do you think? JW?
Flags: needinfo?(ayang) → needinfo?(jwwang)
https://hg.mozilla.org/mozilla-central/rev/06451617ab35
Assignee: nobody → jyavenard
Status: NEW → RESOLVED
Closed: 10 years ago
status-firefox42: affected → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla42
BlankDecoder serves the purpose to test EME on platforms where a working MSE decoder is not available. The point of EME tests is to test if key messages are exchanged/handled correctly in conformance with the spec. So I think using BlankDecoder is fine to keep playback going as well as EME key sessions.
Flags: needinfo?(jwwang)
status-firefox40: --- → unaffected
status-firefox41: --- → unaffected
status-firefox-esr38: --- → unaffected
Flags: needinfo?(ryanvm)
(In reply to Jean-Yves Avenard [:jya] from comment #374) > test_eme_playback.html is a different problem ; should be separated from > this bug I think Spun off to bug 1193351.
See Also: → 1193351
You need to log in before you can comment on or make changes to this bug.