Bug 1522547 - Add more logs to MediaKeys, use PRIu32 for printing where appropriate. r=cpearce
authorBryce Van Dyk <bvandyk@mozilla.com>
Tue, 05 Mar 2019 16:21:28 +0000
changeset 520331 c273b07bc5f06aa68c6d8d2ce7074941a9075cad
parent 520330 c092112f933effac6fbedd252a99bc0fdf0f9411
child 520332 153245ec86c26f88beba43d7858cf5c517e22d84
push id10862
push userffxbld-merge
push dateMon, 11 Mar 2019 13:01:11 +0000
treeherdermozilla-beta@a2e7f5c935da [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewerscpearce
bugs1522547
milestone67.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 1522547 - Add more logs to MediaKeys, use PRIu32 for printing where appropriate. r=cpearce - Add more logging to MediaKeys. - Replace the instances of the %d formatter with PRIu32 when printing the PromiseId type (which has the underlying uint32_t type). Differential Revision: https://phabricator.services.mozilla.com/D21981
dom/media/eme/MediaKeys.cpp
--- a/dom/media/eme/MediaKeys.cpp
+++ b/dom/media/eme/MediaKeys.cpp
@@ -80,16 +80,17 @@ void MediaKeys::Terminated() {
   if (mElement) {
     mElement->DecodeError(NS_ERROR_DOM_MEDIA_CDM_ERR);
   }
 
   Shutdown();
 }
 
 void MediaKeys::Shutdown() {
+  EME_LOG("MediaKeys[%p]::Shutdown()", this);
   if (mProxy) {
     mProxy->Shutdown();
     mProxy = nullptr;
   }
 
   RefPtr<MediaKeys> kungFuDeathGrip = this;
 
   for (auto iter = mPromises.Iter(); !iter.Done(); iter.Next()) {
@@ -154,20 +155,21 @@ already_AddRefed<DetailedPromise> MediaK
   return DetailedPromise::Create(global, aRv, aName);
 }
 
 PromiseId MediaKeys::StorePromise(DetailedPromise* aPromise) {
   static uint32_t sEMEPromiseCount = 1;
   MOZ_ASSERT(aPromise);
   uint32_t id = sEMEPromiseCount++;
 
-  EME_LOG("MediaKeys[%p]::StorePromise() id=%d", this, id);
+  EME_LOG("MediaKeys[%p]::StorePromise() id=%" PRIu32, this, id);
 
   // Keep MediaKeys alive for the lifetime of its promises. Any still-pending
   // promises are rejected in Shutdown().
+  EME_LOG("MediaKeys[%p]::StorePromise() calling AddRef()", this);
   AddRef();
 
 #ifdef DEBUG
   // We should not have already stored this promise!
   for (auto iter = mPromises.ConstIter(); !iter.Done(); iter.Next()) {
     MOZ_ASSERT(iter.Data() != aPromise);
   }
 #endif
@@ -181,35 +183,44 @@ void MediaKeys::ConnectPendingPromiseIdW
   // Should only be called from MediaKeySession::GenerateRequest.
   mPromiseIdToken.Put(aId, aToken);
   EME_LOG(
       "MediaKeys[%p]::ConnectPendingPromiseIdWithToken() id=%u => token(%u)",
       this, aId, aToken);
 }
 
 already_AddRefed<DetailedPromise> MediaKeys::RetrievePromise(PromiseId aId) {
+  EME_LOG("MediaKeys[%p]::RetrievePromise(aId=%" PRIu32 ")", this, aId);
   if (!mPromises.Contains(aId)) {
-    NS_WARNING(
-        nsPrintfCString("Tried to retrieve a non-existent promise id=%d", aId)
-            .get());
+    EME_LOG("MediaKeys[%p]::RetrievePromise(aId=%" PRIu32
+            ") tried to retrieve non-existent promise!",
+            this, aId);
+    NS_WARNING(nsPrintfCString(
+                   "Tried to retrieve a non-existent promise id=%" PRIu32, aId)
+                   .get());
     return nullptr;
   }
   RefPtr<DetailedPromise> promise;
   mPromises.Remove(aId, getter_AddRefs(promise));
+  EME_LOG("MediaKeys[%p]::RetrievePromise(aId=%" PRIu32 ") calling Release()",
+          this, aId);
   Release();
   return promise.forget();
 }
 
 void MediaKeys::RejectPromise(PromiseId aId, nsresult aExceptionCode,
                               const nsCString& aReason) {
-  EME_LOG("MediaKeys[%p]::RejectPromise(%d, 0x%" PRIx32 ")", this, aId,
+  EME_LOG("MediaKeys[%p]::RejectPromise(%" PRIu32 ", 0x%" PRIx32 ")", this, aId,
           static_cast<uint32_t>(aExceptionCode));
 
   RefPtr<DetailedPromise> promise(RetrievePromise(aId));
   if (!promise) {
+    EME_LOG("MediaKeys[%p]::RejectPromise(%" PRIu32 ", 0x%" PRIx32
+            ") couldn't retrieve promise! Bailing!",
+            this, aId, static_cast<uint32_t>(aExceptionCode));
     return;
   }
 
   // This promise could be a createSession or loadSession promise,
   // so we might have a pending session waiting to be resolved into
   // the promise on success. We've been directed to reject to promise,
   // so we can throw away the corresponding session object.
   uint32_t token = 0;
@@ -219,16 +230,19 @@ void MediaKeys::RejectPromise(PromiseId 
     mPromiseIdToken.Remove(aId);
   }
 
   MOZ_ASSERT(NS_FAILED(aExceptionCode));
   promise->MaybeReject(aExceptionCode, aReason);
 
   if (mCreatePromiseId == aId) {
     // Note: This will probably destroy the MediaKeys object!
+    EME_LOG("MediaKeys[%p]::RejectPromise(%" PRIu32 ", 0x%" PRIx32
+            ") calling Release()",
+            this, aId, static_cast<uint32_t>(aExceptionCode));
     Release();
   }
 }
 
 void MediaKeys::OnSessionIdReady(MediaKeySession* aSession) {
   if (!aSession) {
     NS_WARNING("Invalid MediaKeySession passed to OnSessionIdReady()");
     return;
@@ -246,17 +260,17 @@ void MediaKeys::OnSessionIdReady(MediaKe
     NS_WARNING(
         "MediaKeySession with invalid sessionId passed to OnSessionIdReady()");
     return;
   }
   mKeySessions.Put(aSession->GetSessionId(), aSession);
 }
 
 void MediaKeys::ResolvePromise(PromiseId aId) {
-  EME_LOG("MediaKeys[%p]::ResolvePromise(%d)", this, aId);
+  EME_LOG("MediaKeys[%p]::ResolvePromise(%" PRIu32 ")", this, aId);
 
   RefPtr<DetailedPromise> promise(RetrievePromise(aId));
   MOZ_ASSERT(!mPromises.Contains(aId));
   if (!promise) {
     return;
   }
 
   uint32_t token = 0;
@@ -303,16 +317,17 @@ class MediaKeysGMPCrashHelper : public G
   }
 
  private:
   WeakPtr<MediaKeys> mMediaKeys;
 };
 
 already_AddRefed<CDMProxy> MediaKeys::CreateCDMProxy(
     nsIEventTarget* aMainThread) {
+  EME_LOG("MediaKeys[%p]::CreateCDMProxy()", this);
   RefPtr<CDMProxy> proxy;
 #ifdef MOZ_WIDGET_ANDROID
   if (IsWidevineKeySystem(mKeySystem)) {
     proxy = new MediaDrmCDMProxy(
         this, mKeySystem,
         mConfig.mDistinctiveIdentifier == MediaKeysRequirement::Required,
         mConfig.mPersistentState == MediaKeysRequirement::Required,
         aMainThread);
@@ -324,16 +339,17 @@ already_AddRefed<CDMProxy> MediaKeys::Cr
         mConfig.mDistinctiveIdentifier == MediaKeysRequirement::Required,
         mConfig.mPersistentState == MediaKeysRequirement::Required,
         aMainThread);
   }
   return proxy.forget();
 }
 
 already_AddRefed<DetailedPromise> MediaKeys::Init(ErrorResult& aRv) {
+  EME_LOG("MediaKeys[%p]::Init()", this);
   RefPtr<DetailedPromise> promise(
       MakePromise(aRv, NS_LITERAL_CSTRING("MediaKeys::Init()")));
   if (aRv.Failed()) {
     return nullptr;
   }
 
   // Determine principal (at creation time) of the MediaKeys object.
   nsCOMPtr<nsIScriptObjectPrincipal> sop = do_QueryInterface(GetParentObject());
@@ -402,33 +418,39 @@ already_AddRefed<DetailedPromise> MediaK
   // it's been initialized. No external refs exist to the MediaKeys while
   // we're waiting for the promise to be resolved, so we must hold a
   // reference to the new MediaKeys object until it's been created,
   // or its creation has failed. Store the id of the promise returned
   // here, and hold a self-reference until that promise is resolved or
   // rejected.
   MOZ_ASSERT(!mCreatePromiseId, "Should only be created once!");
   mCreatePromiseId = StorePromise(promise);
+  EME_LOG("MediaKeys[%p]::Init() calling AddRef()", this);
   AddRef();
   mProxy->Init(mCreatePromiseId, NS_ConvertUTF8toUTF16(origin),
                NS_ConvertUTF8toUTF16(topLevelOrigin),
                KeySystemToGMPName(mKeySystem));
 
   return promise.forget();
 }
 
 void MediaKeys::OnCDMCreated(PromiseId aId, const uint32_t aPluginId) {
+  EME_LOG("MediaKeys[%p]::OnCDMCreated(aId=%" PRIu32 ", aPluginId=%" PRIu32 ")",
+          this, aId, aPluginId);
   RefPtr<DetailedPromise> promise(RetrievePromise(aId));
   if (!promise) {
     return;
   }
   RefPtr<MediaKeys> keys(this);
-  EME_LOG("MediaKeys[%p]::OnCDMCreated() resolve promise id=%d", this, aId);
+
   promise->MaybeResolve(keys);
   if (mCreatePromiseId == aId) {
+    EME_LOG("MediaKeys[%p]::OnCDMCreated(aId=%" PRIu32 ", aPluginId=%" PRIu32
+            ") calling Release()",
+            this, aId, aPluginId);
     Release();
   }
 
   MediaKeySystemAccess::NotifyObservers(mParent, mKeySystem,
                                         MediaKeySystemStatus::Cdm_created);
 }
 
 static bool IsSessionTypeSupported(const MediaKeySessionType aSessionType,
@@ -441,18 +463,20 @@ static bool IsSessionTypeSupported(const
     // No other session types supported.
     return false;
   }
   return aConfig.mSessionTypes.Value().Contains(ToString(aSessionType));
 }
 
 already_AddRefed<MediaKeySession> MediaKeys::CreateSession(
     JSContext* aCx, MediaKeySessionType aSessionType, ErrorResult& aRv) {
+  EME_LOG("MediaKeys[%p]::CreateSession(aCx=%p, aSessionType=%" PRIu8 ")", this,
+          aCx, static_cast<uint8_t>(aSessionType));
   if (!IsSessionTypeSupported(aSessionType, mConfig)) {
-    EME_LOG("MediaKeys[%p] CreateSession() failed, unsupported session type",
+    EME_LOG("MediaKeys[%p]::CreateSession() failed, unsupported session type",
             this);
     aRv.Throw(NS_ERROR_DOM_NOT_SUPPORTED_ERR);
     return nullptr;
   }
 
   if (!mProxy) {
     NS_WARNING("Tried to use a MediaKeys which lost its CDM");
     aRv.Throw(NS_ERROR_DOM_INVALID_STATE_ERR);
@@ -465,23 +489,27 @@ already_AddRefed<MediaKeySession> MediaK
       aCx, GetParentObject(), this, mKeySystem, aSessionType, aRv);
 
   if (aRv.Failed()) {
     return nullptr;
   }
   DDLINKCHILD("session", session.get());
 
   // Add session to the set of sessions awaiting their sessionId being ready.
+  EME_LOG("MediaKeys[%p]::CreateSession(aCx=%p, aSessionType=%" PRIu8
+          ") putting session with token=%" PRIu32 " into mPendingSessions",
+          this, aCx, static_cast<uint8_t>(aSessionType), session->Token());
   mPendingSessions.Put(session->Token(), session);
 
   return session.forget();
 }
 
 void MediaKeys::OnSessionLoaded(PromiseId aId, bool aSuccess) {
-  EME_LOG("MediaKeys[%p]::OnSessionLoaded() resolve promise id=%d", this, aId);
+  EME_LOG("MediaKeys[%p]::OnSessionLoaded() resolve promise id=%" PRIu32, this,
+          aId);
 
   ResolvePromiseWithResult(aId, aSuccess);
 }
 
 template <typename T>
 void MediaKeys::ResolvePromiseWithResult(PromiseId aId, const T& aResult) {
   RefPtr<DetailedPromise> promise(RetrievePromise(aId));
   if (!promise) {
@@ -501,16 +529,17 @@ already_AddRefed<MediaKeySession> MediaK
     const nsAString& aSessionId) {
   RefPtr<MediaKeySession> session;
   mKeySessions.Get(aSessionId, getter_AddRefs(session));
   return session.forget();
 }
 
 already_AddRefed<MediaKeySession> MediaKeys::GetPendingSession(
     uint32_t aToken) {
+  EME_LOG("MediaKeys[%p]::GetPendingSession(aToken=%" PRIu32 ")", this, aToken);
   RefPtr<MediaKeySession> session;
   mPendingSessions.Get(aToken, getter_AddRefs(session));
   mPendingSessions.Remove(aToken);
   return session.forget();
 }
 
 bool MediaKeys::IsBoundToMediaElement() const {
   MOZ_ASSERT(NS_IsMainThread());
@@ -596,16 +625,16 @@ already_AddRefed<Promise> MediaKeys::Get
 void MediaKeys::ResolvePromiseWithKeyStatus(PromiseId aId,
                                             MediaKeyStatus aMediaKeyStatus) {
   RefPtr<DetailedPromise> promise(RetrievePromise(aId));
   if (!promise) {
     return;
   }
   RefPtr<MediaKeys> keys(this);
   EME_LOG(
-      "MediaKeys[%p]::ResolvePromiseWithKeyStatus() resolve promise id=%d, "
-      "keystatus=%" PRIu8,
+      "MediaKeys[%p]::ResolvePromiseWithKeyStatus() resolve promise id=%" PRIu32
+      ", keystatus=%" PRIu8,
       this, aId, static_cast<uint8_t>(aMediaKeyStatus));
   promise->MaybeResolve(aMediaKeyStatus);
 }
 
 }  // namespace dom
 }  // namespace mozilla