Closed Bug 1129071 Opened 9 years ago Closed 9 years ago

Intermittent test_eme_stream_capture_blocked.html | short-cenc.mp4-0_case2 got error event; [object Event] | called finish() multiple times

Categories

(Core :: Audio/Video, defect)

Product:
Core
Component:
Audio/Video
Platform:
x86
Windows 8.1
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla38
Tracking Flags:
Tracking Status
firefox36 --- unaffected
firefox37 --- fixed
firefox38 --- fixed
firefox-esr31 --- unaffected

People

(Reporter: RyanVM, Assigned: jya)

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

Add log error should we run out of memory
2.15 KB, patch
ajones
: review+
lmandel
: approval-mozilla-aurora+
Details | Diff | Splinter Review 
06:25:14 INFO - 205 INFO TEST-PASS | dom/media/test/test_eme_stream_capture_blocked.html | [06:25:14.10] short-cenc.mp4-1_case3 should reach loadeddata
06:25:14 INFO - 206 INFO TEST-PASS | dom/media/test/test_eme_stream_capture_blocked.html | [06:25:14.10] short-cenc.mp4-1_case3 Should throw an error calling mozCaptureStreamUntilEnded an EME video.
06:25:14 INFO - 207 INFO [finished short-cenc.mp4-1_case3] remaining= gizmo-frag-cencinit.mp4-2_case1,gizmo-frag-cencinit.mp4-2_case2,gizmo-frag-cencinit.mp4-2_case3
06:25:14 INFO - 208 INFO TEST-PASS | dom/media/test/test_eme_stream_capture_blocked.html | [finished short-cenc.mp4-1_case3] Length of array should match number of running tests
06:25:14 INFO - 209 INFO [06:25:14.11] short-cenc.mp4-1_case3 canplay
06:25:14 INFO - 210 INFO [06:25:14.11] short-cenc.mp4-1_case3 canplaythrough
06:25:14 INFO - 211 INFO [06:25:14.15] short-cenc.mp4-0_case2 error
06:25:14 INFO - 212 INFO TEST-UNEXPECTED-FAIL | dom/media/test/test_eme_stream_capture_blocked.html | short-cenc.mp4-0_case2 got error event; [object Event] - expected PASS
06:25:14 INFO - 213 INFO [object Event]
06:25:14 INFO - 214 INFO MEMORY STAT vsize after test: 852783104
06:25:14 INFO - 215 INFO MEMORY STAT vsizeMaxContiguous after test: 8030964973568
06:25:14 INFO - 216 INFO MEMORY STAT residentFast after test: 203571200
06:25:14 INFO - 217 INFO MEMORY STAT heapAllocated after test: 53273378
06:25:14 INFO - 218 INFO [06:25:14.27] short-cenc.mp4-0_case3 error
06:25:14 INFO - 219 INFO TEST-UNEXPECTED-FAIL | dom/media/test/test_eme_stream_capture_blocked.html | short-cenc.mp4-0_case3 got error event; [object Event] - expected PASS
06:25:14 INFO - 220 INFO [object Event]
06:25:14 INFO - 221 ERROR [SimpleTest.finish()] this test already called finish!
06:25:14 INFO - 222 INFO TEST-UNEXPECTED-ERROR | dom/media/test/test_eme_stream_capture_blocked.html | called finish() multiple times
06:25:14 INFO - TEST-INFO took 163ms
06:25:14 INFO - 223 INFO [06:25:14.28] short-cenc.mp4-1_case2 error
06:25:14 INFO - 224 INFO TEST-UNEXPECTED-FAIL | dom/media/test/test_eme_stream_capture_blocked.html | short-cenc.mp4-1_case2 got error event; [object Event] - expected PASS
06:25:14 INFO - 225 INFO [object Event]
06:25:14 INFO - 226 ERROR [SimpleTest.finish()] this test already called finish!
06:25:14 INFO - 227 INFO TEST-UNEXPECTED-ERROR | dom/media/test/test_eme_stream_capture_blocked.html | called finish() multiple times
06:25:14 INFO - TEST-INFO
06:25:14 INFO - 228 INFO [06:25:14.29] short-cenc.mp4-1_case3 error
06:25:14 INFO - 229 INFO TEST-UNEXPECTED-FAIL | dom/media/test/test_eme_stream_capture_blocked.html | short-cenc.mp4-1_case3 got error event; [object Event] - expected PASS
06:25:14 INFO - 230 INFO [object Event]
06:25:14 INFO - 231 ERROR [SimpleTest.finish()] this test already called finish!
06:25:14 INFO - 232 INFO TEST-UNEXPECTED-ERROR | dom/media/test/test_eme_stream_capture_blocked.html | called finish() multiple times
06:25:14 INFO - TEST-INFO
06:25:14 INFO - E/MPEG4Extractor( 3284): No width or height, assuming worst case 1080p
06:25:14 INFO - E/MPEG4Extractor( 3284): No width or height, assuming worst case 1080p
06:25:14 INFO - E/MPEG4Extractor( 3284): No width or height, assuming worst case 1080p
06:25:14 INFO - 233 INFO TEST-OK | dom/media/test/test_eme_stream_capture_blocked.html |
Flags: needinfo?(jwwang)
Assignee: nobody → jwwang
Status: NEW → ASSIGNED
Flags: needinfo?(jwwang)
(In reply to TBPL Robot from comment #3)

08:41:18     INFO -  107 INFO TEST-START | dom/media/test/test_eme_playback.html
08:41:18     INFO -  ++DOMWINDOW == 15 (000000793ABD9400) [pid = 3036] [serial = 144] [outer = 00000079498D5400]
08:41:18     INFO -  W/MPEG4Extractor( 3036): Error -1004 parsing chuck at offset 0 looking for first track
08:41:18     INFO -  I/SampleTable( 3036): There are reordered frames present.
08:41:18     INFO -  file=[xpconnect wrapped nsILocalFile @ 0x674c3eab00 (native @ 0x674bea1780)]
08:41:18     INFO -  [3036] WARNING: '!stream->LastReadFailed(&failure)', file c:/builds/moz2_slave/fx-team-w64-d-0000000000000000/build/dom/media/fmp4/MP4Reader.cpp, line 92
08:41:18     INFO -  W/MPEG4Extractor( 3036): Error -1004 parsing chuck at offset 0 looking for first track
08:41:18     INFO -  I/SampleTable( 3036): There are reordered frames present.
08:41:18     INFO -  [3036] WARNING: '!stream->LastReadFailed(&failure)', file c:/builds/moz2_slave/fx-team-w64-d-0000000000000000/build/dom/media/fmp4/MP4Reader.cpp, line 92
08:41:18     INFO -  [3036] WARNING: '!stream->LastReadFailed(&failure)', file c:/builds/moz2_slave/fx-team-w64-d-0000000000000000/build/dom/media/fmp4/MP4Reader.cpp, line 92
08:41:18     INFO -  Hit MOZ_CRASH() at c:/builds/moz2_slave/fx-team-w64-d-0000000000000000/build/memory/mozjemalloc/jemalloc.c:1610

It looks like something wrong to the MP4 reader...
Flags: needinfo?(jyavenard)
That tests always times out for me on my mac; but I don't hit that failure...

Have to see what changes was made right before 2015-02-03 11:29:40 PST.

The only change to the MP4 Demuxer was dynamic memory allocation. Previously it would have allocated a fix buffer and use that to parse the muxed file, without ever checking if there was enough space to store the read content....

Now, we allocates what we need and the memory allocation is fallible.
Looking at that file, the biggest block allocated is 1084 bytes which is tiny. So either we really do hit an OOM, or the read is corrupted somehow and reports an invalid size.

That's if this is change is caused by rev:68581d6d62cd 

Otherwise, there's another regression somewhere
Flags: needinfo?(jyavenard)
@jwwang: correction, I do see that error, yet the test passes on my two machines (10.10 and ubuntu 14.04 VM)


Wouldn't those error be more an indication of a problem?
14:51:03     INFO -  ###!!! [Parent][DispatchAsyncMessage] Error: (msgtype=0x520014,name=PGMPDecryptor::Msg_KeyStatusChanged) Processing error: message was deserialized, but the handler returned false (indicating failure)
14:51:03     INFO -  IPDL protocol error: Handler for KeyStatusChanged returned error code
14:51:03     INFO -  ###!!! [Parent][DispatchAsyncMessage] Error: (msgtype=0x520014,name=PGMPDecryptor::Msg_KeyStatusChanged) Processing error: message was deserialized, but the handler returned false (indicating failure)
14:51:03     INFO -  IPDL protocol error: Handler for KeyStatusChanged returned error code
14:51:03     INFO -  ###!!! [Parent][DispatchAsyncMessage] Error: (msgtype=0x520014,name=PGMPDecryptor::Msg_KeyStatusChanged) Processing error: message was deserialized, but the handler returned false (indicating failure)
Flags: needinfo?(edwin)
I saw that locally, and filed bug 1129720 for that.
(In reply to Jean-Yves Avenard [:jya] from comment #9)
> @jwwang: correction, I do see that error, yet the test passes on my two
> machines (10.10 and ubuntu 14.04 VM)
> 
> Wouldn't those error be more an indication of a problem?

/me appends bug 1129720 to todo list
Flags: needinfo?(edwin)
Adding some logging should we hit a OOM condition
Attachment #8559558 - Flags: review?(ajones)
Assignee: jwwang → jyavenard
Here is a log of a test that did succeed.
http://ftp.mozilla.org/pub/mozilla.org/firefox/try-builds/jyavenard@mozilla.com-63534c67d5dc/try-win64-debug/try_win8_64-debug_test-mochitest-3-bm110-tests1-windows-build617.txt.gz

In it you see both:
19:25:04     INFO -  [1780] WARNING: Trying to use a dead GMP decrypter!: file c:\builds\moz2_slave\try-w64-d-00000000000000000000\build\dom\media\gmp\GMPDecryptorParent.cpp, line 273
19:25:04     INFO -  IPDL protocol error: Handler for KeyStatusChanged returned error code
19:25:04     INFO -  ###!!! [Parent][DispatchAsyncMessage] Error: (msgtype=0x520014,name=PGMPDecryptor::Msg_KeyStatusChanged) Processing error: message was deserialized, but the handler returned false (indicating failure)

and 
19:25:00     INFO -  W/MPEG4Extractor( 1780): Error -1004 parsing chuck at offset 0 looking for first track
19:25:00     INFO -  I/SampleTable( 1780): There are reordered frames present.
19:25:00     INFO -  [1780] WARNING: '!stream->LastReadFailed(&failure)', file c:/builds/moz2_slave/try-w64-d-00000000000000000000/build/dom/media/fmp4/MP4Reader.cpp, line 92
19:25:00     INFO -  [1780] WARNING: '!stream->LastReadFailed(&failure)', file c:/builds/moz2_slave/try-w64-d-00000000000000000000/build/dom/media/fmp4/MP4Reader.cpp, line 92
19:25:00     INFO -  [1780] WARNING: '!stream->LastReadFailed(&failure)', file c:/builds/moz2_slave/try-w64-d-00000000000000000000/build/dom/media/fmp4/MP4Reader.cpp, line 92
19:25:01     INFO -  E/MPEG4Extractor( 1780): No width or height, assuming worst case 1080p

so probably read herring.
Attachment #8559558 - Flags: review?(ajones) → review+
https://hg.mozilla.org/mozilla-central/rev/79c5866ba7db
Status: ASSIGNED → RESOLVED
Closed: 9 years ago
status-firefox38: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla38
Comment on attachment 8559558 [details] [diff] [review]
Add log error should we run out of memory

Approval Request Comment
[Feature/regressing bug #]: MSE
[User impact if declined]: Less consistent testing, harder to track down issues.
[Describe test coverage new/current, TreeHerder]: Landed on m-c.
[Risks and why]: Minimal. Logging change only.
[String/UUID change made/needed]: None.

I'd like this in 37 so we can directly compare logs.
Attachment #8559558 - Flags: approval-mozilla-aurora?
Comment on attachment 8559558 [details] [diff] [review]
Add log error should we run out of memory

Log only changes. Aurora+
Attachment #8559558 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: