Closed Bug 1114826 Opened 5 years ago Closed 5 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)

36 Branch
x86_64
macOS
defect
Not set

Tracking

()

RESOLVED FIXED
mozilla38
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)

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: 5 years ago
Depends on: 1101308
Resolution: --- → WORKSFORME
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: 5 years ago5 years ago
Flags: in-testsuite+
Resolution: --- → FIXED
Target Milestone: --- → mozilla38
You need to log in before you can comment on or make changes to this bug.