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

RESOLVED FIXED in Firefox 42

Status

()

Product:
Core
Component:
Audio/Video
Type:
defect
Status:
RESOLVED FIXED
Opened:
4 years ago
Updated:
4 years ago

People

(Reporter: RyanVM, Assigned: jya)

Tracking

({intermittent-failure})

Version:
Trunk
Target:
mozilla42
Platform:
ARM
Gonk (Firefox OS)
Points:
---

Firefox Tracking Flags

(firefox40 unaffected, firefox41 unaffected, firefox42 fixed, firefox-esr38 unaffected)

Details

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)
See Also: → 1186722
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