Bug 1315850 - Add more logging to Chromium CDM actors. r=gerald draft
authorChris Pearce <cpearce@mozilla.com>
Thu, 09 Mar 2017 11:42:12 +1300
changeset 504165 b7de793c7676ace43d34a9556ef803e1bd3df239
parent 504164 cf303b0d792dfd86f1056529eb4c081d84fc2e82
child 504166 67575a02290ddb871510dd88f59fdab77658b3ce
push id50748
push userbmo:cpearce@mozilla.com
push dateFri, 24 Mar 2017 01:10:17 +0000
reviewersgerald
bugs1315850
milestone55.0a1
Bug 1315850 - Add more logging to Chromium CDM actors. r=gerald MozReview-Commit-ID: 2DcprLAE1bg
dom/media/gmp/ChromiumCDMChild.cpp
dom/media/gmp/ChromiumCDMParent.cpp
dom/media/gmp/ChromiumCDMProxy.cpp
--- a/dom/media/gmp/ChromiumCDMChild.cpp
+++ b/dom/media/gmp/ChromiumCDMChild.cpp
@@ -4,16 +4,17 @@
  * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
 
 #include "ChromiumCDMChild.h"
 #include "GMPContentChild.h"
 #include "WidevineUtils.h"
 #include "GMPLog.h"
 #include "GMPPlatform.h"
 #include "mozilla/Unused.h"
+#include "nsPrintfCString.h"
 #include "base/time.h"
 
 namespace mozilla {
 namespace gmp {
 
 ChromiumCDMChild::ChromiumCDMChild(GMPContentChild* aPlugin)
   : mPlugin(aPlugin)
 {
@@ -24,30 +25,35 @@ ChromiumCDMChild::Init(cdm::ContentDecry
 {
   mCDM = aCDM;
   MOZ_ASSERT(mCDM);
 }
 
 void
 ChromiumCDMChild::TimerExpired(void* aContext)
 {
+  GMP_LOG("ChromiumCDMChild::TimerExpired(context=0x%p)", aContext);
   if (mCDM) {
     mCDM->TimerExpired(aContext);
   }
 }
 
 cdm::Buffer*
 ChromiumCDMChild::Allocate(uint32_t aCapacity)
 {
+  GMP_LOG("ChromiumCDMChild::Allocate(capacity=%" PRIu32 ")", aCapacity);
   return new WidevineBuffer(aCapacity);
 }
 
 void
 ChromiumCDMChild::SetTimer(int64_t aDelayMs, void* aContext)
 {
+  GMP_LOG("ChromiumCDMChild::SetTimer(delay=%" PRId64 ", context=0x%p)",
+          aDelayMs,
+          aContext);
   RefPtr<ChromiumCDMChild> self(this);
   SetTimerOnMainThread(NewGMPTask([self, aContext]() {
     self->TimerExpired(aContext);
   }), aDelayMs);
 }
 
 cdm::Time
 ChromiumCDMChild::GetCurrentWallTime()
@@ -55,61 +61,101 @@ ChromiumCDMChild::GetCurrentWallTime()
   return base::Time::Now().ToDoubleT();
 }
 
 void
 ChromiumCDMChild::OnResolveNewSessionPromise(uint32_t aPromiseId,
                                              const char* aSessionId,
                                              uint32_t aSessionIdSize)
 {
+  GMP_LOG("ChromiumCDMChild::OnResolveNewSessionPromise(pid=%" PRIu32
+          ", sid=%s)",
+          aPromiseId,
+          aSessionId);
   Unused << SendOnResolveNewSessionPromise(aPromiseId,
                                            nsCString(aSessionId, aSessionIdSize));
 }
 
 void ChromiumCDMChild::OnResolvePromise(uint32_t aPromiseId)
 {
+  GMP_LOG("ChromiumCDMChild::OnResolvePromise(pid=%" PRIu32 ")", aPromiseId);
   Unused << SendOnResolvePromise(aPromiseId);
 }
 
 void
 ChromiumCDMChild::OnRejectPromise(uint32_t aPromiseId,
                                   cdm::Error aError,
                                   uint32_t aSystemCode,
                                   const char* aErrorMessage,
                                   uint32_t aErrorMessageSize)
 {
+  GMP_LOG("ChromiumCDMChild::OnRejectPromise(pid=%" PRIu32 ", err=%" PRIu32
+          " code=%" PRIu32 ", msg='%s')",
+          aPromiseId,
+          aError,
+          aSystemCode,
+          aErrorMessage);
   Unused << SendOnRejectPromise(aPromiseId,
-                                aError,
+                                static_cast<uint32_t>(aError),
                                 aSystemCode,
                                 nsCString(aErrorMessage, aErrorMessageSize));
 }
 
 void
 ChromiumCDMChild::OnSessionMessage(const char* aSessionId,
                                    uint32_t aSessionIdSize,
                                    cdm::MessageType aMessageType,
                                    const char* aMessage,
                                    uint32_t aMessageSize,
                                    const char* aLegacyDestinationUrl,
                                    uint32_t aLegacyDestinationUrlLength)
 {
+  GMP_LOG("ChromiumCDMChild::OnSessionMessage(sid=%s, type=%" PRIu32
+          " size=%" PRIu32 ")",
+          aSessionId,
+          aMessageType,
+          aMessageSize);
   nsTArray<uint8_t> message;
   message.AppendElements(aMessage, aMessageSize);
   Unused << SendOnSessionMessage(nsCString(aSessionId, aSessionIdSize),
-                                 aMessageType,
+                                 static_cast<uint32_t>(aMessageType),
                                  message);
 }
 
+static nsCString
+ToString(const cdm::KeyInformation* aKeysInfo, uint32_t aKeysInfoCount)
+{
+  nsCString str;
+  for (uint32_t i = 0; i < aKeysInfoCount; i++) {
+    nsCString keyId;
+    const cdm::KeyInformation& key = aKeysInfo[i];
+    for (size_t k = 0; k < key.key_id_size; k++) {
+      keyId.Append(nsPrintfCString("%hhX", key.key_id[k]));
+    }
+    if (!str.IsEmpty()) {
+      str.AppendLiteral(",");
+    }
+    str.Append(keyId);
+    str.AppendLiteral("=");
+    str.AppendInt(key.status);
+  }
+  return str;
+}
+
 void
 ChromiumCDMChild::OnSessionKeysChange(const char *aSessionId,
                                       uint32_t aSessionIdSize,
                                       bool aHasAdditionalUsableKey,
                                       const cdm::KeyInformation* aKeysInfo,
                                       uint32_t aKeysInfoCount)
 {
+  GMP_LOG("ChromiumCDMChild::OnSessionKeysChange(sid=%s) keys={%s}",
+          aSessionId,
+          ToString(aKeysInfo, aKeysInfoCount).get());
+
   nsTArray<CDMKeyInformation> keys;
   keys.SetCapacity(aKeysInfoCount);
   for (uint32_t i = 0; i < aKeysInfoCount; i++) {
     const cdm::KeyInformation& key = aKeysInfo[i];
     nsTArray<uint8_t> kid;
     kid.AppendElements(key.key_id, key.key_id_size);
     keys.AppendElement(CDMKeyInformation(kid, key.status, key.system_code));
   }
@@ -117,77 +163,100 @@ ChromiumCDMChild::OnSessionKeysChange(co
                                     keys);
 }
 
 void
 ChromiumCDMChild::OnExpirationChange(const char* aSessionId,
                                      uint32_t aSessionIdSize,
                                      cdm::Time aNewExpiryTime)
 {
+  GMP_LOG("ChromiumCDMChild::OnExpirationChange(sid=%s, time=%lf)",
+          aSessionId,
+          aNewExpiryTime);
   Unused << SendOnExpirationChange(nsCString(aSessionId, aSessionIdSize),
                                    aNewExpiryTime);
 }
 
 void
 ChromiumCDMChild::OnSessionClosed(const char* aSessionId,
                                   uint32_t aSessionIdSize)
 {
+  GMP_LOG("ChromiumCDMChild::OnSessionClosed(sid=%s)", aSessionId);
   Unused << SendOnSessionClosed(nsCString(aSessionId, aSessionIdSize));
 }
 
 void
 ChromiumCDMChild::OnLegacySessionError(const char* aSessionId,
                                        uint32_t aSessionIdLength,
                                        cdm::Error aError,
                                        uint32_t aSystemCode,
                                        const char* aErrorMessage,
                                        uint32_t aErrorMessageLength)
 {
-  Unused << SendOnLegacySessionError(nsCString(aSessionId, aSessionIdLength),
-                                     aError,
-                                     aSystemCode,
-                                     nsCString(aErrorMessage, aErrorMessageLength));
+  GMP_LOG("ChromiumCDMChild::OnLegacySessionError(sid=%s, error=%" PRIu32
+          " msg='%s')",
+          aSessionId,
+          aError,
+          aErrorMessage);
+  Unused << SendOnLegacySessionError(
+    nsCString(aSessionId, aSessionIdLength),
+    static_cast<uint32_t>(aError),
+    aSystemCode,
+    nsCString(aErrorMessage, aErrorMessageLength));
 }
 
 cdm::FileIO*
 ChromiumCDMChild::CreateFileIO(cdm::FileIOClient * aClient)
 {
+  GMP_LOG("ChromiumCDMChild::CreateFileIO()");
   return nullptr;
 }
 
 mozilla::ipc::IPCResult
 ChromiumCDMChild::RecvInit(const bool& aAllowDistinctiveIdentifier,
                            const bool& aAllowPersistentState)
 {
+  GMP_LOG("ChromiumCDMChild::RecvInit(distinctiveId=%d, persistentState=%d)",
+          aAllowDistinctiveIdentifier,
+          aAllowPersistentState);
   if (mCDM) {
     mCDM->Initialize(aAllowDistinctiveIdentifier, aAllowPersistentState);
   }
   return IPC_OK();
 }
 
 mozilla::ipc::IPCResult
 ChromiumCDMChild::RecvSetServerCertificate(const uint32_t& aPromiseId,
                                            nsTArray<uint8_t>&& aServerCert)
 
 {
+  GMP_LOG("ChromiumCDMChild::RecvSetServerCertificate() certlen=%zu",
+          aServerCert.Length());
   if (mCDM) {
     mCDM->SetServerCertificate(aPromiseId,
                                aServerCert.Elements(),
                                aServerCert.Length());
   }
   return IPC_OK();
 }
 
 mozilla::ipc::IPCResult
 ChromiumCDMChild::RecvCreateSessionAndGenerateRequest(
   const uint32_t& aPromiseId,
   const uint32_t& aSessionType,
   const uint32_t& aInitDataType,
   nsTArray<uint8_t>&& aInitData)
 {
+  GMP_LOG("ChromiumCDMChild::RecvCreateSessionAndGenerateRequest("
+          "pid=%" PRIu32 ", sessionType=%" PRIu32 ", initDataType=%" PRIu32
+          ") initDataLen=%zu",
+          aPromiseId,
+          aSessionType,
+          aInitDataType,
+          aInitData.Length());
   MOZ_ASSERT(aSessionType <= cdm::SessionType::kPersistentKeyRelease);
   MOZ_ASSERT(aInitDataType <= cdm::InitDataType::kWebM);
   if (mCDM) {
     mCDM->CreateSessionAndGenerateRequest(aPromiseId,
                                           static_cast<cdm::SessionType>(aSessionType),
                                           static_cast<cdm::InitDataType>(aInitDataType),
                                           aInitData.Elements(),
                                           aInitData.Length());
@@ -195,80 +264,98 @@ ChromiumCDMChild::RecvCreateSessionAndGe
   return IPC_OK();
 }
 
 mozilla::ipc::IPCResult
 ChromiumCDMChild::RecvUpdateSession(const uint32_t& aPromiseId,
                                     const nsCString& aSessionId,
                                     nsTArray<uint8_t>&& aResponse)
 {
+  GMP_LOG("ChromiumCDMChild::RecvUpdateSession(pid=%" PRIu32
+          ", sid=%s) responseLen=%zu",
+          aPromiseId,
+          aSessionId.get(),
+          aResponse.Length());
   if (mCDM) {
     mCDM->UpdateSession(aPromiseId,
                         aSessionId.get(),
                         aSessionId.Length(),
                         aResponse.Elements(),
                         aResponse.Length());
   }
   return IPC_OK();
 }
 
 mozilla::ipc::IPCResult
 ChromiumCDMChild::RecvCloseSession(const uint32_t& aPromiseId,
                                    const nsCString& aSessionId)
 {
+  GMP_LOG("ChromiumCDMChild::RecvCloseSession(pid=%" PRIu32 ", sid=%s)",
+          aPromiseId,
+          aSessionId.get());
   if (mCDM) {
     mCDM->CloseSession(aPromiseId, aSessionId.get(), aSessionId.Length());
   }
   return IPC_OK();
 }
 
 mozilla::ipc::IPCResult
 ChromiumCDMChild::RecvRemoveSession(const uint32_t& aPromiseId,
                                     const nsCString& aSessionId)
 {
+  GMP_LOG("ChromiumCDMChild::RecvRemoveSession(pid=%" PRIu32 ", sid=%s)",
+          aPromiseId,
+          aSessionId.get());
   if (mCDM) {
     mCDM->RemoveSession(aPromiseId, aSessionId.get(), aSessionId.Length());
   }
   return IPC_OK();
 }
 
 mozilla::ipc::IPCResult
 ChromiumCDMChild::RecvDecrypt(const CDMInputBuffer& aBuffer)
 {
+  GMP_LOG("ChromiumCDMChild::RecvDecrypt()");
   return IPC_OK();
 }
 
 mozilla::ipc::IPCResult
 ChromiumCDMChild::RecvInitializeVideoDecoder(
   const CDMVideoDecoderConfig& aConfig)
 {
+  GMP_LOG("ChromiumCDMChild::RecvInitializeVideoDecoder()");
   return IPC_OK();
 }
 
 mozilla::ipc::IPCResult
 ChromiumCDMChild::RecvDeinitializeVideoDecoder()
 {
+  GMP_LOG("ChromiumCDMChild::RecvDeinitializeVideoDecoder()");
   return IPC_OK();
 }
 
 mozilla::ipc::IPCResult
 ChromiumCDMChild::RecvResetVideoDecoder()
 {
+  GMP_LOG("ChromiumCDMChild::RecvResetVideoDecoder()");
   return IPC_OK();
 }
 
 mozilla::ipc::IPCResult
 ChromiumCDMChild::RecvDecryptAndDecodeFrame(const CDMInputBuffer& aBuffer)
 {
+  GMP_LOG("ChromiumCDMChild::RecvDecryptAndDecodeFrame()");
   return IPC_OK();
 }
 
 mozilla::ipc::IPCResult
 ChromiumCDMChild::RecvDestroy()
 {
+  GMP_LOG("ChromiumCDMChild::RecvDestroy()");
+
   if (mCDM) {
     mCDM->Destroy();
     mCDM = nullptr;
   }
 
   Unused << Send__delete__(this);
 
   return IPC_OK();
--- a/dom/media/gmp/ChromiumCDMParent.cpp
+++ b/dom/media/gmp/ChromiumCDMParent.cpp
@@ -5,113 +5,131 @@
 
 #include "ChromiumCDMParent.h"
 #include "mozilla/gmp/GMPTypes.h"
 #include "GMPContentChild.h"
 #include "mozilla/Unused.h"
 #include "ChromiumCDMProxy.h"
 #include "mozilla/dom/MediaKeyMessageEventBinding.h"
 #include "content_decryption_module.h"
+#include "GMPLog.h"
 
 namespace mozilla {
 namespace gmp {
 
 ChromiumCDMParent::ChromiumCDMParent(GMPContentParent* aContentParent,
                                      uint32_t aPluginId)
   : mPluginId(aPluginId)
   , mContentParent(aContentParent)
 {
+  GMP_LOG(
+    "ChromiumCDMParent::ChromiumCDMParent(this=%p, contentParent=%p, id=%u)",
+    this,
+    aContentParent,
+    aPluginId);
 }
 
 bool
 ChromiumCDMParent::Init(ChromiumCDMProxy* aProxy,
                         bool aAllowDistinctiveIdentifier,
                         bool aAllowPersistentState)
 {
+  GMP_LOG("ChromiumCDMParent::Init(this=%p)", this);
   mProxy = aProxy;
   return SendInit(aAllowDistinctiveIdentifier, aAllowPersistentState);
 }
 
 void
 ChromiumCDMParent::CreateSession(uint32_t aCreateSessionToken,
                                  uint32_t aSessionType,
                                  uint32_t aInitDataType,
                                  uint32_t aPromiseId,
                                  const nsTArray<uint8_t>& aInitData)
 {
+  GMP_LOG("ChromiumCDMParent::CreateSession(this=%p)", this);
   if (!SendCreateSessionAndGenerateRequest(
         aPromiseId, aSessionType, aInitDataType, aInitData)) {
     RejectPromise(
       aPromiseId,
       NS_ERROR_DOM_INVALID_STATE_ERR,
       NS_LITERAL_CSTRING("Failed to send generateRequest to CDM process."));
     return;
   }
   mPromiseToCreateSessionToken.Put(aPromiseId, aCreateSessionToken);
 }
 
 void
 ChromiumCDMParent::SetServerCertificate(uint32_t aPromiseId,
                                         const nsTArray<uint8_t>& aCert)
 {
+  GMP_LOG("ChromiumCDMParent::SetServerCertificate(this=%p)", this);
   if (!SendSetServerCertificate(aPromiseId, aCert)) {
     RejectPromise(
       aPromiseId,
       NS_ERROR_DOM_INVALID_STATE_ERR,
       NS_LITERAL_CSTRING("Failed to send setServerCertificate to CDM process"));
   }
 }
 
 void
 ChromiumCDMParent::UpdateSession(const nsCString& aSessionId,
                                  uint32_t aPromiseId,
                                  const nsTArray<uint8_t>& aResponse)
 {
+  GMP_LOG("ChromiumCDMParent::UpdateSession(this=%p)", this);
   if (!SendUpdateSession(aPromiseId, aSessionId, aResponse)) {
     RejectPromise(
       aPromiseId,
       NS_ERROR_DOM_INVALID_STATE_ERR,
       NS_LITERAL_CSTRING("Failed to send updateSession to CDM process"));
   }
 }
 
 void
 ChromiumCDMParent::CloseSession(const nsCString& aSessionId,
                                 uint32_t aPromiseId)
 {
+  GMP_LOG("ChromiumCDMParent::CloseSession(this=%p)", this);
   if (!SendCloseSession(aPromiseId, aSessionId)) {
     RejectPromise(
       aPromiseId,
       NS_ERROR_DOM_INVALID_STATE_ERR,
       NS_LITERAL_CSTRING("Failed to send closeSession to CDM process"));
   }
 }
 
 void
 ChromiumCDMParent::RemoveSession(const nsCString& aSessionId,
                                  uint32_t aPromiseId)
 {
+  GMP_LOG("ChromiumCDMParent::RemoveSession(this=%p)", this);
   if (!SendRemoveSession(aPromiseId, aSessionId)) {
     RejectPromise(
       aPromiseId,
       NS_ERROR_DOM_INVALID_STATE_ERR,
       NS_LITERAL_CSTRING("Failed to send removeSession to CDM process"));
   }
 }
 
 ipc::IPCResult
 ChromiumCDMParent::Recv__delete__()
 {
+  GMP_LOG("ChromiumCDMParent::Recv__delete__(this=%p)", this);
   return IPC_OK();
 }
 
 ipc::IPCResult
 ChromiumCDMParent::RecvOnResolveNewSessionPromise(const uint32_t& aPromiseId,
                                                   const nsCString& aSessionId)
 {
+  GMP_LOG("ChromiumCDMParent::RecvOnResolveNewSessionPromise(this=%p, pid=%u, "
+          "sid=%s)",
+          this,
+          aPromiseId,
+          aSessionId.get());
   if (!mProxy) {
     return IPC_OK();
   }
 
   Maybe<uint32_t> token = mPromiseToCreateSessionToken.GetAndRemove(aPromiseId);
   if (token.isNothing()) {
     RejectPromise(aPromiseId,
                   NS_ERROR_DOM_INVALID_STATE_ERR,
@@ -129,16 +147,19 @@ ChromiumCDMParent::RecvOnResolveNewSessi
   ResolvePromise(aPromiseId);
 
   return IPC_OK();
 }
 
 void
 ChromiumCDMParent::ResolvePromise(uint32_t aPromiseId)
 {
+  GMP_LOG(
+    "ChromiumCDMParent::ResolvePromise(this=%p, pid=%u)", this, aPromiseId);
+
   if (!mProxy) {
     return;
   }
   NS_DispatchToMainThread(NewRunnableMethod<uint32_t>(
     mProxy, &ChromiumCDMProxy::ResolvePromise, aPromiseId));
 }
 
 ipc::IPCResult
@@ -175,16 +196,18 @@ ToNsresult(uint32_t aError)
   return NS_ERROR_DOM_TIMEOUT_ERR; // Note: Unique placeholder.
 }
 
 void
 ChromiumCDMParent::RejectPromise(uint32_t aPromiseId,
                                  nsresult aError,
                                  const nsCString& aErrorMessage)
 {
+  GMP_LOG(
+    "ChromiumCDMParent::RejectPromise(this=%p, pid=%u)", this, aPromiseId);
   if (!mProxy) {
     return;
   }
   NS_DispatchToMainThread(NewRunnableMethod<uint32_t, nsresult, nsCString>(
     mProxy,
     &ChromiumCDMProxy::RejectPromise,
     aPromiseId,
     aError,
@@ -216,16 +239,19 @@ ToDOMMessageType(uint32_t aMessageType)
   return dom::MediaKeyMessageType::License_request;
 }
 
 ipc::IPCResult
 ChromiumCDMParent::RecvOnSessionMessage(const nsCString& aSessionId,
                                         const uint32_t& aMessageType,
                                         nsTArray<uint8_t>&& aMessage)
 {
+  GMP_LOG("ChromiumCDMParent::RecvOnSessionMessage(this=%p, sid=%s)",
+          this,
+          aSessionId.get());
   if (!mProxy) {
     return IPC_OK();
   }
   RefPtr<CDMProxy> proxy = mProxy;
   nsString sid = NS_ConvertUTF8toUTF16(aSessionId);
   dom::MediaKeyMessageType messageType = ToDOMMessageType(aMessageType);
   nsTArray<uint8_t> msg(Move(aMessage));
   NS_DispatchToMainThread(
@@ -258,16 +284,17 @@ ToDOMMediaKeyStatus(uint32_t aStatus)
   return dom::MediaKeyStatus::Internal_error;
 }
 
 ipc::IPCResult
 ChromiumCDMParent::RecvOnSessionKeysChange(
   const nsCString& aSessionId,
   nsTArray<CDMKeyInformation>&& aKeysInfo)
 {
+  GMP_LOG("ChromiumCDMParent::RecvOnSessionKeysChange(this=%p)", this);
   if (!mProxy) {
     return IPC_OK();
   }
   bool keyStatusesChange = false;
   {
     CDMCaps::AutoLock caps(mProxy->Capabilites());
     for (size_t i = 0; i < aKeysInfo.Length(); i++) {
       keyStatusesChange |=
@@ -285,46 +312,51 @@ ChromiumCDMParent::RecvOnSessionKeysChan
   }
   return IPC_OK();
 }
 
 ipc::IPCResult
 ChromiumCDMParent::RecvOnExpirationChange(const nsCString& aSessionId,
                                           const double& aSecondsSinceEpoch)
 {
+  GMP_LOG("ChromiumCDMParent::RecvOnExpirationChange(this=%p) time=%lf",
+          this,
+          aSecondsSinceEpoch);
   if (!mProxy) {
     return IPC_OK();
   }
   NS_DispatchToMainThread(NewRunnableMethod<nsString, UnixTime>(
     mProxy,
     &ChromiumCDMProxy::OnExpirationChange,
     NS_ConvertUTF8toUTF16(aSessionId),
     GMPTimestamp(aSecondsSinceEpoch * 1000)));
   return IPC_OK();
 }
 
 ipc::IPCResult
 ChromiumCDMParent::RecvOnSessionClosed(const nsCString& aSessionId)
 {
+  GMP_LOG("ChromiumCDMParent::RecvOnSessionClosed(this=%p)", this);
   if (!mProxy) {
     return IPC_OK();
   }
   NS_DispatchToMainThread(
     NewRunnableMethod<nsString>(mProxy,
                                 &ChromiumCDMProxy::OnSessionClosed,
                                 NS_ConvertUTF8toUTF16(aSessionId)));
   return IPC_OK();
 }
 
 ipc::IPCResult
 ChromiumCDMParent::RecvOnLegacySessionError(const nsCString& aSessionId,
                                             const uint32_t& aError,
                                             const uint32_t& aSystemCode,
                                             const nsCString& aMessage)
 {
+  GMP_LOG("ChromiumCDMParent::RecvOnLegacySessionError(this=%p)", this);
   if (!mProxy) {
     return IPC_OK();
   }
   NS_DispatchToMainThread(
     NewRunnableMethod<nsString, nsresult, uint32_t, nsString>(
       mProxy,
       &ChromiumCDMProxy::OnSessionError,
       NS_ConvertUTF8toUTF16(aSessionId),
@@ -351,19 +383,21 @@ ipc::IPCResult
 ChromiumCDMParent::RecvDecodeFailed(const uint32_t& aStatus)
 {
   return IPC_OK();
 }
 
 ipc::IPCResult
 ChromiumCDMParent::RecvShutdown()
 {
+  GMP_LOG("ChromiumCDMParent::RecvShutdown(this=%p)", this);
   // TODO: SendDestroy(), call Terminated.
   return IPC_OK();
 }
 
 void
 ChromiumCDMParent::ActorDestroy(ActorDestroyReason aWhy)
 {
+  GMP_LOG("ChromiumCDMParent::ActorDestroy(this=%p, reason=%d)", this, aWhy);
 }
 
 } // namespace gmp
 } // namespace mozilla
--- a/dom/media/gmp/ChromiumCDMProxy.cpp
+++ b/dom/media/gmp/ChromiumCDMProxy.cpp
@@ -41,19 +41,22 @@ void
 ChromiumCDMProxy::Init(PromiseId aPromiseId,
                        const nsAString& aOrigin,
                        const nsAString& aTopLevelOrigin,
                        const nsAString& aGMPName)
 {
   MOZ_ASSERT(NS_IsMainThread());
   NS_ENSURE_TRUE_VOID(!mKeys.IsNull());
 
-  EME_LOG("ChromiumCDMProxy::Init(%s, %s)",
-          NS_ConvertUTF16toUTF8(aOrigin).get(),
-          NS_ConvertUTF16toUTF8(aTopLevelOrigin).get());
+  EME_LOG(
+    "ChromiumCDMProxy::Init (pid=%u, origin=%s, topLevelOrigin=%s, gmp=%s)",
+    aPromiseId,
+    NS_ConvertUTF16toUTF8(aOrigin).get(),
+    NS_ConvertUTF16toUTF8(aTopLevelOrigin).get(),
+    NS_ConvertUTF16toUTF8(aGMPName).get());
 
   if (!mGMPThread) {
     RejectPromise(
       aPromiseId,
       NS_ERROR_DOM_INVALID_STATE_ERR,
       NS_LITERAL_CSTRING("Couldn't get GMP thread ChromiumCDMProxy::Init"));
     return;
   }
@@ -173,16 +176,22 @@ ToCDMInitDataType(const nsAString& aInit
 void
 ChromiumCDMProxy::CreateSession(uint32_t aCreateSessionToken,
                                 dom::MediaKeySessionType aSessionType,
                                 PromiseId aPromiseId,
                                 const nsAString& aInitDataType,
                                 nsTArray<uint8_t>& aInitData)
 {
   MOZ_ASSERT(NS_IsMainThread());
+  EME_LOG("ChromiumCDMProxy::CreateSession(token=%u, type=%d, pid=%u) "
+          "initDataLen=%zu",
+          aCreateSessionToken,
+          (int)aSessionType,
+          aPromiseId,
+          aInitData.Length());
 
   uint32_t sessionType = ToCDMSessionType(aSessionType);
   uint32_t initDataType = ToCDMInitDataType(aInitDataType);
 
   mGMPThread->Dispatch(
     NewRunnableMethod<uint32_t,
                       uint32_t,
                       uint32_t,
@@ -206,94 +215,117 @@ ChromiumCDMProxy::LoadSession(PromiseId 
                 NS_LITERAL_CSTRING("loadSession is not supported"));
 }
 
 void
 ChromiumCDMProxy::SetServerCertificate(PromiseId aPromiseId,
                                        nsTArray<uint8_t>& aCert)
 {
   MOZ_ASSERT(NS_IsMainThread());
+  EME_LOG("ChromiumCDMProxy::SetServerCertificate(pid=%u) certLen=%zu",
+          aPromiseId,
+          aCert.Length());
 
   mGMPThread->Dispatch(NewRunnableMethod<uint32_t, nsTArray<uint8_t>>(
     mCDM,
     &gmp::ChromiumCDMParent::SetServerCertificate,
     aPromiseId,
     Move(aCert)));
 }
 
 void
 ChromiumCDMProxy::UpdateSession(const nsAString& aSessionId,
                                 PromiseId aPromiseId,
                                 nsTArray<uint8_t>& aResponse)
 {
   MOZ_ASSERT(NS_IsMainThread());
+  EME_LOG("ChromiumCDMProxy::UpdateSession(sid='%s', pid=%u) responseLen=%zu",
+          NS_ConvertUTF16toUTF8(aSessionId).get(),
+          aPromiseId,
+          aResponse.Length());
 
   mGMPThread->Dispatch(NewRunnableMethod<nsCString, uint32_t, nsTArray<uint8_t>>(
       mCDM,
       &gmp::ChromiumCDMParent::UpdateSession,
       NS_ConvertUTF16toUTF8(aSessionId),
       aPromiseId,
       Move(aResponse)));
 }
 
 void
 ChromiumCDMProxy::CloseSession(const nsAString& aSessionId,
                                PromiseId aPromiseId)
 {
+  MOZ_ASSERT(NS_IsMainThread());
+  EME_LOG("ChromiumCDMProxy::CloseSession(sid='%s', pid=%u)",
+          NS_ConvertUTF16toUTF8(aSessionId).get(),
+          aPromiseId);
+
   mGMPThread->Dispatch(NewRunnableMethod<nsCString, uint32_t>(
     mCDM,
     &gmp::ChromiumCDMParent::CloseSession,
     NS_ConvertUTF16toUTF8(aSessionId),
     aPromiseId));
 }
 
 void
 ChromiumCDMProxy::RemoveSession(const nsAString& aSessionId,
                                 PromiseId aPromiseId)
 {
+  MOZ_ASSERT(NS_IsMainThread());
+  EME_LOG("ChromiumCDMProxy::RemoveSession(sid='%s', pid=%u)",
+          NS_ConvertUTF16toUTF8(aSessionId).get(),
+          aPromiseId);
+
   mGMPThread->Dispatch(NewRunnableMethod<nsCString, uint32_t>(
     mCDM,
     &gmp::ChromiumCDMParent::RemoveSession,
     NS_ConvertUTF16toUTF8(aSessionId),
     aPromiseId));
 }
 
 void
 ChromiumCDMProxy::Shutdown()
 {
+  EME_LOG("ChromiumCDMProxy::Shutdown()");
 }
 
 void
 ChromiumCDMProxy::RejectPromise(PromiseId aId,
                                 nsresult aCode,
                                 const nsCString& aReason)
 {
   if (!NS_IsMainThread()) {
     nsCOMPtr<nsIRunnable> task;
     task = NewRunnableMethod<PromiseId, nsresult, nsCString>(
       this, &ChromiumCDMProxy::RejectPromise, aId, aCode, aReason);
     NS_DispatchToMainThread(task);
     return;
   }
+  EME_LOG("ChromiumCDMProxy::RejectPromise(pid=%u, code=0x%x, reason='%s')",
+          aId,
+          static_cast<uint32_t>(aCode),
+          aReason.get());
   if (!mKeys.IsNull()) {
     mKeys->RejectPromise(aId, aCode, aReason);
   }
 }
 
 void
 ChromiumCDMProxy::ResolvePromise(PromiseId aId)
 {
   if (!NS_IsMainThread()) {
     nsCOMPtr<nsIRunnable> task;
     task = NewRunnableMethod<PromiseId>(
       this, &ChromiumCDMProxy::ResolvePromise, aId);
     NS_DispatchToMainThread(task);
     return;
   }
 
+  EME_LOG("ChromiumCDMProxy::ResolvePromise(pid=%u)", aId);
   if (!mKeys.IsNull()) {
     mKeys->ResolvePromise(aId);
   } else {
     NS_WARNING("ChromiumCDMProxy unable to resolve promise!");
   }
 }
 
 const nsCString&
@@ -302,16 +334,20 @@ ChromiumCDMProxy::GetNodeId() const
   return mNodeId;
 }
 
 void
 ChromiumCDMProxy::OnSetSessionId(uint32_t aCreateSessionToken,
                                  const nsAString& aSessionId)
 {
   MOZ_ASSERT(NS_IsMainThread());
+  EME_LOG("ChromiumCDMProxy::OnSetSessionId(token=%u, sid='%s')",
+          aCreateSessionToken,
+          NS_ConvertUTF16toUTF8(aSessionId).get());
+
   if (mKeys.IsNull()) {
     return;
   }
   RefPtr<dom::MediaKeySession> session(
     mKeys->GetPendingSession(aCreateSessionToken));
   if (session) {
     session->SetSessionId(aSessionId);
   }