1303662 - GMP child crashes while trying to release the decryptor during mediaKeySession.close.

Status: RESOLVED FIXED

(Testing :: web-platform-tests, defect)

Description

[Kilik Kuo [:kikuo] (inactive)]

A follow-up from https://bugzilla.mozilla.org/show_bug.cgi?id=1289968#c11.

2 keyids are initialized by mediaKeySession.update, but the corresponding mDecryptor for each keyid in our ClearKey implementation shall be created already during. mediaKeySession.generateRequest. [1]

[1] https://dxr.mozilla.org/mozilla-central/source/testing/web-platform/tests/encrypted-media/Google/encrypted-media-keystatuses.html#38-41,139-142,148

Comment 1

[Kilik Kuo [:kikuo] (inactive)]

...
0:27.03 PROCESS_OUTPUT: ProcessReader (pid:4677) "[GMPThread]: D/GMP GMPDecryptorParent[7f2afa513680]::CreateSession(token=0, promiseId=2, aInitData='
AAECAwQFBgcICQoLDA0ODw==')"
 0:27.03 PROCESS_OUTPUT: ProcessReader (pid:4677) "[Main Thread]: D/EME MediaKeySession[7f2afa69a980,''] GenerateRequest() sent, promiseId=2 initData(b
ase64)='AAECAwQFBgcICQoLDA0ODw==' initDataType='webm'"
 0:27.03 PROCESS_OUTPUT: ProcessReader (pid:4677) "ClearKeySessionManager::CreateSession type:webm"
 0:27.03 PROCESS_OUTPUT: ProcessReader (pid:4677) "ClearKeySession ctor 0x7f2114b5a940"
 0:27.03 PROCESS_OUTPUT: ProcessReader (pid:4677) "ClearKeySession::Init"
 0:27.03 PROCESS_OUTPUT: ProcessReader (pid:4677) "ClearKeyDecryptionManager::ExpectKeyId 03020100..."
 0:27.03 PROCESS_OUTPUT: ProcessReader (pid:4677) "ClearKeyDecryptionManager::SeenKeyId f"
 0:27.03 PROCESS_OUTPUT: ProcessReader (pid:4677) "ClearKeyDecryptor ctor >>>>> this(14b5abb0)"
 0:27.04 PROCESS_OUTPUT: ProcessReader (pid:4677) "[GMPThread]: D/GMP GMPDecryptorParent[7f2afa513680]::RecvSetSessionId(token=0, sessionId='1')"
 0:27.04 PROCESS_OUTPUT: ProcessReader (pid:4677) "[GMPThread]: D/GMP GMPDecryptorParent[7f2afa513680]::RecvResolvePromise(promiseId=2)"
 0:27.04 PROCESS_OUTPUT: ProcessReader (pid:4677) "[Main Thread]: D/EME MediaKeySession[7f2afa69a980,'1'] session Id set"
 0:27.04 PROCESS_OUTPUT: ProcessReader (pid:4677) "[Main Thread]: D/EME MediaKeys[7f2afa6f5530]::ResolvePromise(2)"
 0:27.04 PROCESS_OUTPUT: ProcessReader (pid:4677) "[GMPThread]: D/GMP GMPDecryptorParent[7f2afa513680]::RecvSessionMessage(sessionId='1', type=0, msg='
eyJraWRzIjpbIkFBRUNBd1FGQmdjSUNRb0xEQTBPRHciXSwidHlwZSI6InRlbXBvcmFyeSJ9')"
 0:27.04 PROCESS_OUTPUT: ProcessReader (pid:4677) "[Main Thread]: D/EME MediaKeySession[7f2afa69a980,'1'] DispatchKeyMessage() type=license-request mes
sage(base64)='eyJraWRzIjpbIkFBRUNBd1FGQmdjSUNRb0xEQTBPRHciXSwidHlwZSI6InRlbXBvcmFyeSJ9'"
 0:27.06 PROCESS_OUTPUT: ProcessReader (pid:4677) "[Main Thread]: D/EME MediaKeys[7f2afa6f5530]::StorePromise() id=3"
 0:27.06 PROCESS_OUTPUT: ProcessReader (pid:4677) "[Main Thread]: D/EME MediaKeySession[7f2afa69a980,'1'] Update() sent to CDM, promiseId=3 Response(ba
se64)='eyJrZXlzIjpbeyJrdHkiOiJvY3QiLCJhbGciOiJBMTI4S1ciLCJraWQiOiJNVEl6IiwiayI6IjY5MWk4V2dVMG50bzd4SXFfT1N1UEEifSx7Imt0eSI6Im9jdCIsImFsZyI6IkExMjhLVyIs
ImtpZCI6Ik5EVTJOemc1TUEiLCJrIjoiUEs3a19Db1M3Mmg3MGhSbzhXTGQ2dyJ9XX0='"
 0:27.06 PROCESS_OUTPUT: ProcessReader (pid:4677) "[GMPThread]: D/GMP GMPDecryptorParent[7f2afa513680]::UpdateSession(sessionId='1', promiseId=3 respon
se='eyJrZXlzIjpbeyJrdHkiOiJvY3QiLCJhbGciOiJBMTI4S1ciLCJraWQiOiJNVEl6IiwiayI6IjY5MWk4V2dVMG50bzd4SXFfT1N1UEEifSx7Imt0eSI6Im9jdCIsImFsZyI6IkExMjhLVyIsImt
pZCI6Ik5EVTJOemc1TUEiLCJrIjoiUEs3a19Db1M3Mmg3MGhSbzhXTGQ2dyJ9XX0=')"
 0:27.06 PROCESS_OUTPUT: ProcessReader (pid:4677) "ClearKeySessionManager::UpdateSession"
 0:27.06 PROCESS_OUTPUT: ProcessReader (pid:4677) "JWK parser skipping string"
 0:27.06 PROCESS_OUTPUT: ProcessReader (pid:4677) "JWK parser skipping string"
 0:27.06 PROCESS_OUTPUT: ProcessReader (pid:4677) "ClearKeyDecryptionManager::InitKey e4333231..."
 0:27.06 PROCESS_OUTPUT: ProcessReader (pid:4677) "ClearKeyDecryptionManager::IsExpectingKeyForId e4333231..."
 0:27.06 PROCESS_OUTPUT: ProcessReader (pid:4677) "ClearKeyDecryptionManager::InitKey 37363534..."
 0:27.06 PROCESS_OUTPUT: ProcessReader (pid:4677) "ClearKeyDecryptionManager::IsExpectingKeyForId 37363534..."
...
...
 0:27.69 PROCESS_OUTPUT: ProcessReader (pid:12006) "ClearKeySessionManager::CloseSession"
 0:27.69 PROCESS_OUTPUT: ProcessReader (pid:12006) "ClearKeySession dtor 0x7f2114b5a940"
 0:27.69 PROCESS_OUTPUT: ProcessReader (pid:12006) "ClearKeyDecryptionManager::SeenKeyId 03020100... t"
 0:27.69 PROCESS_OUTPUT: ProcessReader (pid:12006) "ClearKeyDecryptionManager::ReleaseKeyId"
 0:27.70 PROCESS_OUTPUT: ProcessReader (pid:12006) "ClearKeyDecryptionManager::SeenKeyId 03020100... t"
 0:27.70 PROCESS_OUTPUT: ProcessReader (pid:12006) "ClearKeyDecryptor dtor; key >>>>>>>>>>>> this(a175ac10)"
...
crashed !


From the log, we can see that ...
1. A ClearKeyDecryptor(14b5abb0) is created with keyId("03020100").  
  ==> keyId is parsed from initData.
2. Two keyIds("e4333231", "37363534") are updated through |ClearKeySessionManager::UpdateSession| wihtout corresponding ClearKeyDecryptors created.
  ==> keyIds are defined in scripts, and converted to uint8 array.
  ==> var key1String = '123';
  ==> var key2String = '4567890';
3. GMP Child crashed during destruction of ClearKeyDecryptor(14b5abb0), because the decryptor tries to print the key which is not initialized. [1]

[1] http://searchfox.org/mozilla-central/source/media/gmp-clearkey/0.1/ClearKeyDecryptionManager.cpp#159

The crash only happens when ClearKey logging functions are enabled.
So, I will modify the log message [1] as a solution of this bug.

But I'm also wondering that should the keyId("03020100") in 1. be the same as the first keyId("e4333231") in 2. ?   Chris, any comments ?
If they should be the same, I would like to check the parser bits in another follow-up bug.

Comment 2

[Kilik Kuo [:kikuo] (inactive)]

Attachment: Bug 1303662 - Avoid accessing uninitialized member while debugging.

Review commit: https://reviewboard.mozilla.org/r/83886/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/83886/

Comment 3

[Chris Pearce [:cpearce (Not reading bugmail)]]

Comment on attachment 8798363 [details]
Bug 1303662 - Avoid accessing uninitialized member while debugging.

https://reviewboard.mozilla.org/r/83886/#review82752

Please log the dtor running on the !HasKey() path, else someone may someday look at the log and think that we're leaking ClearKeyDecryptors.

Comment 4

[Kilik Kuo [:kikuo] (inactive)]

Comment on attachment 8798363 [details]
Bug 1303662 - Avoid accessing uninitialized member while debugging.

https://reviewboard.mozilla.org/r/83886/#review82752

Good point ! Thanks :)

Comment 5

[Kilik Kuo [:kikuo] (inactive)]

Comment on attachment 8798363 [details]
Bug 1303662 - Avoid accessing uninitialized member while debugging.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/83886/diff/1-2/

Comment 6

[Kilik Kuo [:kikuo] (inactive)]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=b8e7111cd334,
try run looks ok.

Comment 7

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/a400e8ddbe2a
Avoid accessing uninitialized member while debugging. r=cpearce

Comment 8

[Phil Ringnalda (:philor)]

https://hg.mozilla.org/mozilla-central/rev/a400e8ddbe2a