Closed Bug 1114826 Opened 11 years ago Closed 11 years ago

Intermittent test_eme_canvas_blocked.html,test_eme_persistent_sessions.html | failed to create MediaKeys object; InvalidStateError: An attempt was made to use an object that is not, or is no longer, usable

Categories

(Core :: Audio/Video, defect)

Product:
Core
Component:
Audio/Video
Version:
36 Branch
Platform:
x86_64
macOS
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: KWierso, Assigned: jwwang)

References

Details

(Keywords: assertion, crash, intermittent-failure)

Attachments

(1 file, 1 obsolete file)

1114826_delay_onsessioncreated-v2.patch
4.04 KB, patch
jwwang
: review+
Details | Diff | Splinter Review
14:20:02 INFO - 2271 INFO TEST-START | dom/media/test/test_eme_canvas_blocked.html 14:20:02 INFO - ++DOMWINDOW == 29 (0x10b8a7c00) [pid = 1001] [serial = 3963] [outer = 0x12d077c00] 14:20:02 INFO - -*-*- UserCustomizations (parent): document created: http://mochi.test:8888/tests/dom/media/test/test_eme_canvas_blocked.html 14:20:02 INFO - -*-*- UserCustomizations (parent): _injectInWindow 14:20:02 INFO - -*-*- UserCustomizations (parent): principal status: 0 14:20:02 INFO - [Parent 1001] WARNING: Silently denied access to property |results|: object is not safely Xrayable (@chrome://specialpowers/content/specialpowersAPI.js:289): file /builds/slave/fx-team-osx64-d-00000000000000/build/src/js/xpconnect/wrappers/XrayWrapper.cpp, line 191 14:20:02 INFO - [Parent 1001] WARNING: Silently denied access to property |results|: object is not safely Xrayable (@chrome://specialpowers/content/specialpowersAPI.js:290): file /builds/slave/fx-team-osx64-d-00000000000000/build/src/js/xpconnect/wrappers/XrayWrapper.cpp, line 191 14:20:02 INFO - I/SampleTable( 1001): There are reordered frames present. 14:20:02 INFO - E/MPEG4Extractor( 1001): No width or height, assuming worst case 1080p 14:20:07 INFO - --DOMWINDOW == 28 (0x10c237c00) [pid = 1001] [serial = 3952] [outer = 0x0] [url = chrome://browser/content/browser.xul] 14:20:07 INFO - --DOMWINDOW == 27 (0x11de1c000) [pid = 1001] [serial = 3956] [outer = 0x0] [url = about:blank] 14:20:12 INFO - --DOMWINDOW == 26 (0x10c238c00) [pid = 1001] [serial = 3953] [outer = 0x0] [url = about:blank] 14:20:12 INFO - --DOMWINDOW == 25 (0x10b8a5800) [pid = 1001] [serial = 3962] [outer = 0x0] [url = http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html] 14:20:12 INFO - --DOMWINDOW == 24 (0x10b89f800) [pid = 1001] [serial = 3951] [outer = 0x0] [url = http://mochi.test:8888/tests/dom/media/test/test_delay_load.html] 14:20:12 INFO - --DOMWINDOW == 23 (0x12330d000) [pid = 1001] [serial = 3961] [outer = 0x0] [url = about:blank] 14:20:12 INFO - [Parent 1001] WARNING: parent WaitForMessage() failed: 0x10004003 (ipc/rcv) timed out: file /builds/slave/fx-team-osx64-d-00000000000000/build/src/ipc/glue/GeckoChildProcessHost.cpp, line 733 14:20:12 INFO - 2272 INFO TEST-PASS | dom/media/test/test_eme_canvas_blocked.html | A valid string reason is expected 14:20:12 INFO - 2273 INFO TEST-PASS | dom/media/test/test_eme_canvas_blocked.html | Reason cannot be empty 14:20:12 INFO - 2274 INFO Started Mon Dec 22 2014 14:20:02 GMT-0800 (PST) (1419286802.265s) 14:20:12 INFO - 2275 INFO TEST-PASS | dom/media/test/test_eme_canvas_blocked.html | [started short-cenc.mp4-0] Length of array should match number of running tests 14:20:12 INFO - 2276 INFO TEST-PASS | dom/media/test/test_eme_canvas_blocked.html | [started gizmo-frag-cencinit.mp4-1] Length of array should match number of running tests 14:20:12 INFO - 2277 INFO [14:20:02.270] short-cenc.mp4-0 loadstart 14:20:12 INFO - 2278 INFO [14:20:02.271] gizmo-frag-cencinit.mp4-1 loadstart 14:20:12 INFO - 2279 INFO [14:20:02.275] gizmo-frag-cencinit.mp4-1 sourceopen 14:20:12 INFO - 2280 INFO [14:20:02.277] gizmo-frag-cencinit.mp4-1 addNextFragment() fetching next fragment gizmo-frag-cencinit.mp4 14:20:12 INFO - 2281 INFO [14:20:02.326] short-cenc.mp4-0 progress 14:20:12 INFO - 2282 INFO [14:20:02.327] short-cenc.mp4-0 got encrypted event 14:20:12 INFO - 2283 INFO [14:20:02.330] short-cenc.mp4-0 progress 14:20:12 INFO - 2284 INFO [14:20:02.331] short-cenc.mp4-0 suspend 14:20:12 INFO - 2285 INFO [14:20:02.355] gizmo-frag-cencinit.mp4-1 fetch of gizmo-frag-cencinit.mp4 complete, appending 14:20:12 INFO - 2286 INFO [14:20:02.359] gizmo-frag-cencinit.mp4-1 progress 14:20:12 INFO - 2287 INFO [14:20:02.361] gizmo-frag-cencinit.mp4-1 addNextFragment() fetching next fragment gizmo-frag-cenc1.m4s 14:20:12 INFO - 2288 INFO [14:20:02.363] gizmo-frag-cencinit.mp4-1 got encrypted event 14:20:12 INFO - 2289 INFO [14:20:02.496] gizmo-frag-cencinit.mp4-1 fetch of gizmo-frag-cenc1.m4s complete, appending 14:20:12 INFO - 2290 INFO [14:20:02.498] gizmo-frag-cencinit.mp4-1 addNextFragment() fetching next fragment gizmo-frag-cenc2.m4s 14:20:12 INFO - 2291 INFO [14:20:02.712] gizmo-frag-cencinit.mp4-1 fetch of gizmo-frag-cenc2.m4s complete, appending 14:20:12 INFO - 2292 INFO [14:20:02.714] gizmo-frag-cencinit.mp4-1 progress 14:20:12 INFO - 2293 INFO [14:20:02.715] gizmo-frag-cencinit.mp4-1 addNextFragment() end of stream 14:20:12 INFO - 2294 INFO [14:20:06.25] gizmo-frag-cencinit.mp4-1 stalled 14:20:12 INFO - 2295 INFO TEST-UNEXPECTED-FAIL | dom/media/test/test_eme_canvas_blocked.html | failed to create MediaKeys object; InvalidStateError: An attempt was made to use an object that is not, or is no longer, usable - expected PASS 14:20:12 INFO - 2296 INFO InvalidStateError: An attempt was made to use an object that is not, or is no longer, usable 14:20:12 INFO - 2297 INFO MEMORY STAT vsize after test: 4226494464 14:20:12 INFO - 2298 INFO MEMORY STAT residentFast after test: 738250752 14:20:12 INFO - 2299 INFO MEMORY STAT heapAllocated after test: 96057832 14:20:12 INFO - 2300 INFO [14:20:12.353] short-cenc.mp4-0 set MediaKeys on <video> element ok 14:20:12 INFO - 2301 INFO TEST-UNEXPECTED-FAIL | dom/media/test/test_eme_canvas_blocked.html | short-cenc.mp4-0 Failed to request key system access2.; TypeError: v.mediaKeys is null - expected PASS 14:20:12 INFO - 2302 INFO TEST-UNEXPECTED-ERROR | dom/media/test/test_eme_canvas_blocked.html | called finish() multiple times 14:20:12 INFO - TEST-INFO took 10262ms 14:20:12 INFO - 2303 INFO TEST-OK | dom/media/test/test_eme_canvas_blocked.html | 14:20:12 INFO - [1035] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/slave/fx-team-osx64-d-00000000000000/build/src/xpcom/base/nsTraceRefcnt.cpp, line 143 14:20:12 INFO - [1035] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/slave/fx-team-osx64-d-00000000000000/build/src/xpcom/base/nsTraceRefcnt.cpp, line 143 14:20:12 INFO - ++DOMWINDOW == 24 (0x10b871c00) [pid = 1001] [serial = 3964] [outer = 0x12d077c00] 14:20:12 INFO - -*-*- UserCustomizations (parent): document created: http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html 14:20:12 INFO - -*-*- UserCustomizations (parent): _injectInWindow 14:20:12 INFO - -*-*- UserCustomizations (parent): principal status: 0 14:20:12 INFO - 2304 INFO TEST-START | dom/media/test/test_eme_persistent_sessions.html
See the TBPLbot comment below for crash/assertion goodness related to this failure as well.
Flags: needinfo?(cpearce)
Keywords: assertion, crash
Summary: Intermittent test_eme_canvas_blocked.html | failed to create MediaKeys object; InvalidStateError: An attempt was made to use an object that is not, or is no longer, usable → Intermittent test_eme_canvas_blocked.html,test_eme_persistent_sessions.html | failed to create MediaKeys object; InvalidStateError: An attempt was made to use an object that is not, or is no longer, usable
Bug 1101308 may help with this.
Flags: needinfo?(cpearce)
(In reply to TBPL Robot from comment #3) > submit_timestamp: 2014-12-23T11:06:28 > log: > https://treeherder.mozilla.org/ui/logviewer.html#?repo=fx-team&job_id=1534114 > repository: fx-team > who: rvandermeulen[at]mozilla[dot]com > machine: t-snow-r4-0135 > buildname: Rev4 MacOSX Snow Leopard 10.6 fx-team debug test mochitest-2 > revision: 0f145e2cc93d > > Assertion failure: false (Should not reach here.), at > /builds/slave/fx-team-osx64-d-00000000000000/build/src/media/gmp-clearkey/0. > 1/ClearKeyStorage.cpp:144 Wait, whut? That shouldn't happen...
Flags: needinfo?(cpearce)
I suspect this was fixed by bug 1101308.
Status: NEW → RESOLVED
Closed: 11 years ago
Depends on: 1101308
Resolution: --- → WORKSFORME
What about comment 6?
Fair point...
Status: RESOLVED → REOPENED
No longer depends on: 1101308
Flags: needinfo?(cpearce)
Resolution: WORKSFORME → ---
Flags: needinfo?(cpearce)
I can repro it on try server. I will add some logs to see if I can get some clues.
OK. I see what's going on. It is possible for GMPStorageChild::CreateRecord() to create 2 records with the same name and GMPStorageChild::RecvWriteComplete() dispatches GMPRecordImpl::WriteComplete() to the wrong record for they share the same name. I think there are 2 options here: 1. Allow at most one record for the given record name. 2. Allow multiple records for the same name and find a way to know which record the request/response is for.
Hmm... GMPDiskStorage::Open() will assert the record name is not opened. It shouldn't be possible to create 2 records with the same name...
(In reply to JW Wang [:jwwang] from comment #58) > Hmm... > > GMPDiskStorage::Open() will assert the record name is not opened. It > shouldn't be possible to create 2 records with the same name... GMPStorageParent::RecvOpen() will return GMPRecordInUse early when mStorage->IsOpen(aRecordName) is true. So it won't hit the assertion in GMPDiskStorage::Open().
00:47:44 INFO - 228 INFO [00:47:44.152] gizmo-frag-cencinit.mp4-3 Closing session with id=4 00:47:44 INFO - 1895718080[10631c070]: ClearKeySessionManager::UpdateSession, StoreData, sid=4 00:47:44 INFO - 1895718080[10631c070]: 106322260 GMPStorageChild::CreateRecord name=4 00:47:44 INFO - 523268096[11ecd5aa0]: GMPParent::RecvOpen: 1237fe7f0 record=4 00:47:44 INFO - 229 INFO [00:47:44.156] gizmo-frag-cencinit.mp4-3 re-created MediaKeys object ok 00:47:44 INFO - 230 INFO [00:47:44.156] gizmo-frag-cencinit.mp4-3 Created recreatedSession, loading sessionId=4 00:47:44 INFO - 523268096[11ecd5aa0]: GMPParent::RecvWrite: 1237fe7f0 record=4 00:47:44 INFO - 1895718080[10631c070]: ClearKeySessionManager::LoadSession, LoadSessionData, sid=4 00:47:44 INFO - 1895718080[10631c070]: 106322260 GMPStorageChild::CreateRecord name=4 00:47:44 INFO - 523268096[11ecd5aa0]: GMPParent::RecvOpen: 1237fe7f0 record=4 00:47:44 INFO - 1895718080[10631c070]: 106322260 GMPStorageChild::RecvWriteComplete name=4 00:47:44 INFO - Assertion failure: false (Should not reach here.), at /builds/slave/try-osx64-d-000000000000000000/build/src/media/gmp-clearkey/0.1/ClearKeyStorage.cpp:143 StoreData() is a 2 round-trip operation which consists of GMPRecord::Open/GMPRecordClient::OpenComplete and GMPRecord::Write/GMPRecordClient::WriteComplete. It is possible for ClearKeySessionManager::LoadSession() to kick in to call GMPStorageChild::CreateRecord() to create another record with the same name before GMPRecordClient::WriteComplete() is received. Then GMPRecordClient::WriteComplete() will be called on the newly created client (ReadRecordClient) to hit the assertion. GMPStorageChild::CreateRecord() should bail out if the requested record name has existed in the hash table. However, ReadData() will fail as well as the test case.
Assignee: nobody → jwwang
Comment on attachment 8561171 [details] [diff] [review] 1114826_delay_onsessioncreated-v1.patch Review of attachment 8561171 [details] [diff] [review]: ----------------------------------------------------------------- ::: dom/media/test/test_eme_persistent_sessions.html @@ +70,5 @@ > var keySystemAccess; > > var v = SetupEME(test, token, > { > + onsessionupdated: function(session) { We start our tests after the session is updated. Otherwise MediaKeySession.update() could collide with MediaKeySession.load(). See comment 67 for the detail. We should really return an error in GMPStorageChild::CreateRecord() if the requested record name has existed in the hash table. However, that will break EME gtests. I will file another bug to fix that.
Attachment #8561171 - Flags: review?(cpearce)
Comment on attachment 8561171 [details] [diff] [review] 1114826_delay_onsessioncreated-v1.patch Review of attachment 8561171 [details] [diff] [review]: ----------------------------------------------------------------- Edwin, please review this for me.
Attachment #8561171 - Flags: review?(cpearce) → review?(edwin)
Blocks: 1130917
Comment on attachment 8561171 [details] [diff] [review] 1114826_delay_onsessioncreated-v1.patch Review of attachment 8561171 [details] [diff] [review]: ----------------------------------------------------------------- ::: dom/media/test/eme.js @@ +266,5 @@ > + session.generateRequest(ev.initDataType, ev.initData).catch(function(reason) { > + // Reject the promise if generateRequest() failed. Otherwise it will > + // be resolve in UpdateSessionFunc(). > + bail(token + ": session.generateRequest failed")(reason); > + reject(); You might end up calling reject() twice. Does that matter?
Attachment #8561171 - Flags: review?(edwin) → review+
Comment on attachment 8561171 [details] [diff] [review] 1114826_delay_onsessioncreated-v1.patch Review of attachment 8561171 [details] [diff] [review]: ----------------------------------------------------------------- ::: dom/media/test/eme.js @@ +266,5 @@ > + session.generateRequest(ev.initDataType, ev.initData).catch(function(reason) { > + // Reject the promise if generateRequest() failed. Otherwise it will > + // be resolve in UpdateSessionFunc(). > + bail(token + ": session.generateRequest failed")(reason); > + reject(); It won't happen according to the spec. https://w3c.github.io/encrypted-media/#widl-MediaKeySession-generateRequest-Promise-void--DOMString-initDataType-BufferSource-initData If the promise is rejected before step 11, "message" won't be queued and UpdateSessionFunc() won't have a chance to reject again.
fix nits.
Attachment #8561171 - Attachment is obsolete: true
Attachment #8561842 - Flags: review+
https://hg.mozilla.org/mozilla-central/rev/df1e73a2888c
Status: REOPENED → RESOLVED
Closed: 11 years ago → 11 years ago
status-firefox38: --- → fixed
Flags: in-testsuite+
Resolution: --- → FIXED
Target Milestone: --- → mozilla38
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: