Bug 1194576 - Add more NSPR logging around GMP*Parent actors. r=gerald

2015-08-14 19:18:19 +12:00 · 2015-08-14 19:18:19 +12:00 · 2ad25b6368
--- a/dom/media/eme/MediaKeySession.cpp
+++ b/dom/media/eme/MediaKeySession.cpp
@ -16,7 +16,7 @@
 #include "mozilla/Move.h"
 #include "nsContentUtils.h"
 #include "mozilla/EMEUtils.h"
-#include "mozilla/Base64.h"
+#include "GMPUtils.h"
 #include "nsPrintfCString.h"

 namespace mozilla {
@ -143,14 +143,7 @@ MediaKeySession::UpdateKeyStatusMap()
      nsPrintfCString("MediaKeySession[%p,'%s'] key statuses change {",
                      this, NS_ConvertUTF16toUTF8(mSessionId).get()));
    for (const CDMCaps::KeyStatus& status : keyStatuses) {
-      nsAutoCString base64KeyId;
-      nsDependentCSubstring rawKeyId(reinterpret_cast<const char*>(status.mId.Elements()),
-                                     status.mId.Length());
-      nsresult rv = Base64Encode(rawKeyId, base64KeyId);
-      if (NS_WARN_IF(NS_FAILED(rv))) {
-        continue;
-      }
-      message.Append(nsPrintfCString(" (%s,%s)", base64KeyId.get(),
+      message.Append(nsPrintfCString(" (%s,%s)", ToBase64(status.mId).get(),
        MediaKeyStatusValues::strings[status.mStatus].value));
    }
    message.Append(" }");
@ -197,17 +190,9 @@ MediaKeySession::GenerateRequest(const nsAString& aInitDataType,
  }

  // Convert initData to base64 for easier logging.
-  // Note: UpdateSession() Move()s the data out of the array, so we have
+  // Note: CreateSession() Move()s the data out of the array, so we have
  // to copy it here.
-  nsAutoCString base64InitData;
-  if (EME_LOG_ENABLED()) {
-    nsDependentCSubstring rawInitData(reinterpret_cast<const char*>(data.Elements()),
-      data.Length());
-    if (NS_FAILED(Base64Encode(rawInitData, base64InitData))) {
-      NS_WARNING("Failed to base64 encode initData for logging");
-    }
-  }
-
+  nsAutoCString base64InitData(ToBase64(data));
  PromiseId pid = mKeys->StorePromise(promise);
  mKeys->GetCDMProxy()->CreateSession(Token(),
                                      mSessionType,
@ -296,14 +281,7 @@ MediaKeySession::Update(const ArrayBufferViewOrArrayBuffer& aResponse, ErrorResu
  // Convert response to base64 for easier logging.
  // Note: UpdateSession() Move()s the data out of the array, so we have
  // to copy it here.
-  nsAutoCString base64Response;
-  if (EME_LOG_ENABLED()) {
-    nsDependentCSubstring rawResponse(reinterpret_cast<const char*>(data.Elements()),
-      data.Length());
-    if (NS_FAILED(Base64Encode(rawResponse, base64Response))) {
-      NS_WARNING("Failed to base64 encode response for logging");
-    }
-  }
+  nsAutoCString base64Response(ToBase64(data));

  PromiseId pid = mKeys->StorePromise(promise);
  mKeys->GetCDMProxy()->UpdateSession(mSessionId,
@ -400,16 +378,10 @@ MediaKeySession::DispatchKeyMessage(MediaKeyMessageType aMessageType,
                                    const nsTArray<uint8_t>& aMessage)
 {
  if (EME_LOG_ENABLED()) {
-    nsAutoCString base64MsgData;
-    nsDependentCSubstring rawMsgData(reinterpret_cast<const char*>(aMessage.Elements()),
-                                     aMessage.Length());
-    if (NS_FAILED(Base64Encode(rawMsgData, base64MsgData))) {
-      NS_WARNING("Failed to base64 encode message for logging");
-    }
    EME_LOG("MediaKeySession[%p,'%s'] DispatchKeyMessage() type=%s message(base64)='%s'",
            this, NS_ConvertUTF16toUTF8(mSessionId).get(),
            MediaKeyMessageTypeValues::strings[uint32_t(aMessageType)].value,
-            base64MsgData.get());
+            ToBase64(aMessage).get());
  }

  nsRefPtr<MediaKeyMessageEvent> event(
--- a/dom/media/gmp/GMPAudioDecoderParent.cpp
+++ b/dom/media/gmp/GMPAudioDecoderParent.cpp
@ -19,6 +19,7 @@ namespace mozilla {

 extern PRLogModuleInfo* GetGMPLog();

+#define LOGV(msg) MOZ_LOG(GetGMPLog(), mozilla::LogLevel::Verbose, msg)
 #define LOGD(msg) MOZ_LOG(GetGMPLog(), mozilla::LogLevel::Debug, msg)
 #define LOG(level, msg) MOZ_LOG(GetGMPLog(), (level), msg)

@ -48,6 +49,8 @@ GMPAudioDecoderParent::InitDecode(GMPAudioCodecType aCodecType,
                                  nsTArray<uint8_t>& aExtraData,
                                  GMPAudioDecoderCallbackProxy* aCallback)
 {
+  LOGD(("GMPAudioDecoderParent[%p]::InitDecode()", this));
+
  if (mIsOpen) {
    NS_WARNING("Trying to re-init an in-use GMP audio decoder!");
    return NS_ERROR_FAILURE;
@ -78,6 +81,8 @@ GMPAudioDecoderParent::InitDecode(GMPAudioCodecType aCodecType,
 nsresult
 GMPAudioDecoderParent::Decode(GMPAudioSamplesImpl& aEncodedSamples)
 {
+  LOGV(("GMPAudioDecoderParent[%p]::Decode() timestamp=%lld",
+        this, aEncodedSamples.TimeStamp()));

  if (!mIsOpen) {
    NS_WARNING("Trying to use a dead GMP Audio decoder!");
@ -100,6 +105,8 @@ GMPAudioDecoderParent::Decode(GMPAudioSamplesImpl& aEncodedSamples)
 nsresult
 GMPAudioDecoderParent::Reset()
 {
+  LOGD(("GMPAudioDecoderParent[%p]::Reset()", this));
+
  if (!mIsOpen) {
    NS_WARNING("Trying to use a dead GMP Audio decoder!");
    return NS_ERROR_FAILURE;
@ -120,6 +127,8 @@ GMPAudioDecoderParent::Reset()
 nsresult
 GMPAudioDecoderParent::Drain()
 {
+  LOGD(("GMPAudioDecoderParent[%p]::Drain()", this));
+
  if (!mIsOpen) {
    NS_WARNING("Trying to use a dead GMP Audio decoder!");
    return NS_ERROR_FAILURE;
@ -141,7 +150,7 @@ GMPAudioDecoderParent::Drain()
 nsresult
 GMPAudioDecoderParent::Close()
 {
-  LOGD(("%s: %p", __FUNCTION__, this));
+  LOGD(("GMPAudioDecoderParent[%p]::Close()", this));
  MOZ_ASSERT(!mPlugin || mPlugin->GMPThread() == NS_GetCurrentThread());

  // Ensure if we've received a Close while waiting for a ResetComplete
@ -166,7 +175,7 @@ GMPAudioDecoderParent::Close()
 nsresult
 GMPAudioDecoderParent::Shutdown()
 {
-  LOGD(("%s: %p", __FUNCTION__, this));
+  LOGD(("GMPAudioDecoderParent[%p]::Shutdown()", this));
  MOZ_ASSERT(!mPlugin || mPlugin->GMPThread() == NS_GetCurrentThread());

  if (mShuttingDown) {
@ -197,6 +206,8 @@ GMPAudioDecoderParent::Shutdown()
 void
 GMPAudioDecoderParent::ActorDestroy(ActorDestroyReason aWhy)
 {
+  LOGD(("GMPAudioDecoderParent[%p]::ActorDestroy(reason=%d)", this, aWhy));
+
  mIsOpen = false;
  mActorDestroyed = true;

@ -220,6 +231,9 @@ GMPAudioDecoderParent::ActorDestroy(ActorDestroyReason aWhy)
 bool
 GMPAudioDecoderParent::RecvDecoded(const GMPAudioDecodedSampleData& aDecoded)
 {
+  LOGV(("GMPAudioDecoderParent[%p]::RecvDecoded() timestamp=%lld",
+        this, aDecoded.mTimeStamp()));
+
  if (!mCallback) {
    return false;
  }
@ -235,6 +249,8 @@ GMPAudioDecoderParent::RecvDecoded(const GMPAudioDecodedSampleData& aDecoded)
 bool
 GMPAudioDecoderParent::RecvInputDataExhausted()
 {
+  LOGV(("GMPAudioDecoderParent[%p]::RecvInputDataExhausted()", this));
+
  if (!mCallback) {
    return false;
  }
@ -248,6 +264,8 @@ GMPAudioDecoderParent::RecvInputDataExhausted()
 bool
 GMPAudioDecoderParent::RecvDrainComplete()
 {
+  LOGD(("GMPAudioDecoderParent[%p]::RecvDrainComplete()", this));
+
  if (!mCallback) {
    return false;
  }
@ -266,6 +284,8 @@ GMPAudioDecoderParent::RecvDrainComplete()
 bool
 GMPAudioDecoderParent::RecvResetComplete()
 {
+  LOGD(("GMPAudioDecoderParent[%p]::RecvResetComplete()", this));
+
  if (!mCallback) {
    return false;
  }
@ -284,6 +304,8 @@ GMPAudioDecoderParent::RecvResetComplete()
 bool
 GMPAudioDecoderParent::RecvError(const GMPErr& aError)
 {
+  LOGD(("GMPAudioDecoderParent[%p]::RecvError(error=%d)", this, aError));
+
  if (!mCallback) {
    return false;
  }
@ -302,6 +324,8 @@ GMPAudioDecoderParent::RecvError(const GMPErr& aError)
 bool
 GMPAudioDecoderParent::RecvShutdown()
 {
+  LOGD(("GMPAudioDecoderParent[%p]::RecvShutdown()", this));
+
  Shutdown();
  return true;
 }
@ -309,6 +333,8 @@ GMPAudioDecoderParent::RecvShutdown()
 bool
 GMPAudioDecoderParent::Recv__delete__()
 {
+  LOGD(("GMPAudioDecoderParent[%p]::Recv__delete__()", this));
+
  if (mPlugin) {
    // Ignore any return code. It is OK for this to fail without killing the process.
    mPlugin->AudioDecoderDestroyed(this);
@ -321,6 +347,8 @@ GMPAudioDecoderParent::Recv__delete__()
 void
 GMPAudioDecoderParent::UnblockResetAndDrain()
 {
+  LOGD(("GMPAudioDecoderParent[%p]::UnblockResetAndDrain()", this));
+
  if (!mCallback) {
    MOZ_ASSERT(!mIsAwaitingResetComplete);
    MOZ_ASSERT(!mIsAwaitingDrainComplete);
--- a/dom/media/gmp/GMPDecryptorParent.cpp
+++ b/dom/media/gmp/GMPDecryptorParent.cpp
@ -9,6 +9,17 @@
 #include "mozilla/unused.h"

 namespace mozilla {
+
+#ifdef LOG
+#undef LOG
+#endif
+
+extern PRLogModuleInfo* GetGMPLog();
+
+#define LOGV(msg) MOZ_LOG(GetGMPLog(), mozilla::LogLevel::Verbose, msg)
+#define LOGD(msg) MOZ_LOG(GetGMPLog(), mozilla::LogLevel::Debug, msg)
+#define LOG(level, msg) MOZ_LOG(GetGMPLog(), (level), msg)
+
 namespace gmp {

 GMPDecryptorParent::GMPDecryptorParent(GMPContentParent* aPlugin)
@ -32,6 +43,8 @@ GMPDecryptorParent::~GMPDecryptorParent()
 nsresult
 GMPDecryptorParent::Init(GMPDecryptorProxyCallback* aCallback)
 {
+  LOGD(("GMPDecryptorParent[%p]::Init()", this));
+
  if (mIsOpen) {
    NS_WARNING("Trying to re-use an in-use GMP decrypter!");
    return NS_ERROR_FAILURE;
@ -51,6 +64,9 @@ GMPDecryptorParent::CreateSession(uint32_t aCreateSessionToken,
                                  const nsTArray<uint8_t>& aInitData,
                                  GMPSessionType aSessionType)
 {
+  LOGD(("GMPDecryptorParent[%p]::CreateSession(token=%u, promiseId=%u, aInitData='%s')",
+        this, aCreateSessionToken, aPromiseId, ToBase64(aInitData).get()));
+
  if (!mIsOpen) {
    NS_WARNING("Trying to use a dead GMP decrypter!");
    return;
@ -64,6 +80,8 @@ void
 GMPDecryptorParent::LoadSession(uint32_t aPromiseId,
                                const nsCString& aSessionId)
 {
+  LOGD(("GMPDecryptorParent[%p]::LoadSession(sessionId='%s', promiseId=%u)",
+        this, aSessionId.get(), aPromiseId));
  if (!mIsOpen) {
    NS_WARNING("Trying to use a dead GMP decrypter!");
    return;
@ -78,6 +96,9 @@ GMPDecryptorParent::UpdateSession(uint32_t aPromiseId,
                                  const nsCString& aSessionId,
                                  const nsTArray<uint8_t>& aResponse)
 {
+  LOGD(("GMPDecryptorParent[%p]::UpdateSession(sessionId='%s', promiseId=%u response='%s')",
+        this, aSessionId.get(), aPromiseId, ToBase64(aResponse).get()));
+
  if (!mIsOpen) {
    NS_WARNING("Trying to use a dead GMP decrypter!");
    return;
@ -91,6 +112,9 @@ void
 GMPDecryptorParent::CloseSession(uint32_t aPromiseId,
                                 const nsCString& aSessionId)
 {
+  LOGD(("GMPDecryptorParent[%p]::CloseSession(sessionId='%s', promiseId=%u)",
+         this, aSessionId.get(), aPromiseId));
+
  if (!mIsOpen) {
    NS_WARNING("Trying to use a dead GMP decrypter!");
    return;
@ -104,6 +128,9 @@ void
 GMPDecryptorParent::RemoveSession(uint32_t aPromiseId,
                                  const nsCString& aSessionId)
 {
+  LOGD(("GMPDecryptorParent[%p]::RemoveSession(sessionId='%s', promiseId=%u)",
+        this, aSessionId.get(), aPromiseId));
+
  if (!mIsOpen) {
    NS_WARNING("Trying to use a dead GMP decrypter!");
    return;
@ -117,6 +144,9 @@ void
 GMPDecryptorParent::SetServerCertificate(uint32_t aPromiseId,
                                         const nsTArray<uint8_t>& aServerCert)
 {
+  LOGD(("GMPDecryptorParent[%p]::SetServerCertificate(promiseId=%u)",
+        this, aPromiseId));
+
  if (!mIsOpen) {
    NS_WARNING("Trying to use a dead GMP decrypter!");
    return;
@ -131,6 +161,8 @@ GMPDecryptorParent::Decrypt(uint32_t aId,
                            const CryptoSample& aCrypto,
                            const nsTArray<uint8_t>& aBuffer)
 {
+  LOGV(("GMPDecryptorParent[%p]::Decrypt(id=%d)", this, aId));
+
  if (!mIsOpen) {
    NS_WARNING("Trying to use a dead GMP decrypter!");
    return;
@ -152,6 +184,9 @@ bool
 GMPDecryptorParent::RecvSetSessionId(const uint32_t& aCreateSessionId,
                                     const nsCString& aSessionId)
 {
+  LOGD(("GMPDecryptorParent[%p]::RecvSetSessionId(token=%u, sessionId='%s')",
+        this, aCreateSessionId, aSessionId.get()));
+
  if (!mIsOpen) {
    NS_WARNING("Trying to use a dead GMP decrypter!");
    return false;
@ -164,6 +199,9 @@ bool
 GMPDecryptorParent::RecvResolveLoadSessionPromise(const uint32_t& aPromiseId,
                                                  const bool& aSuccess)
 {
+  LOGD(("GMPDecryptorParent[%p]::RecvResolveLoadSessionPromise(promiseId=%u)",
+        this, aPromiseId));
+
  if (!mIsOpen) {
    NS_WARNING("Trying to use a dead GMP decrypter!");
    return false;
@ -175,6 +213,9 @@ GMPDecryptorParent::RecvResolveLoadSessionPromise(const uint32_t& aPromiseId,
 bool
 GMPDecryptorParent::RecvResolvePromise(const uint32_t& aPromiseId)
 {
+  LOGD(("GMPDecryptorParent[%p]::RecvResolvePromise(promiseId=%u)",
+        this, aPromiseId));
+
  if (!mIsOpen) {
    NS_WARNING("Trying to use a dead GMP decrypter!");
    return false;
@ -206,6 +247,9 @@ GMPDecryptorParent::RecvRejectPromise(const uint32_t& aPromiseId,
                                      const GMPDOMException& aException,
                                      const nsCString& aMessage)
 {
+  LOGD(("GMPDecryptorParent[%p]::RecvRejectPromise(promiseId=%u, exception=%d, msg='%s')",
+        this, aException, aMessage.get()));
+
  if (!mIsOpen) {
    NS_WARNING("Trying to use a dead GMP decrypter!");
    return false;
@ -219,6 +263,9 @@ GMPDecryptorParent::RecvSessionMessage(const nsCString& aSessionId,
                                       const GMPSessionMessageType& aMessageType,
                                       nsTArray<uint8_t>&& aMessage)
 {
+  LOGD(("GMPDecryptorParent[%p]::RecvSessionMessage(sessionId='%s', type=%d, msg='%s')",
+        this, aSessionId.get(), aMessageType, ToBase64(aMessage).get()));
+
  if (!mIsOpen) {
    NS_WARNING("Trying to use a dead GMP decrypter!");
    return false;
@ -231,6 +278,9 @@ bool
 GMPDecryptorParent::RecvExpirationChange(const nsCString& aSessionId,
                                         const double& aExpiryTime)
 {
+  LOGD(("GMPDecryptorParent[%p]::RecvExpirationChange(sessionId='%s', expiry=%lf)",
+        this, aSessionId.get(), aExpiryTime));
+
  if (!mIsOpen) {
    NS_WARNING("Trying to use a dead GMP decrypter!");
    return false;
@ -242,6 +292,9 @@ GMPDecryptorParent::RecvExpirationChange(const nsCString& aSessionId,
 bool
 GMPDecryptorParent::RecvSessionClosed(const nsCString& aSessionId)
 {
+  LOGD(("GMPDecryptorParent[%p]::RecvSessionClosed(sessionId='%s')",
+        this, aSessionId.get()));
+
  if (!mIsOpen) {
    NS_WARNING("Trying to use a dead GMP decrypter!");
    return false;
@ -256,6 +309,10 @@ GMPDecryptorParent::RecvSessionError(const nsCString& aSessionId,
                                     const uint32_t& aSystemCode,
                                     const nsCString& aMessage)
 {
+  LOGD(("GMPDecryptorParent[%p]::RecvSessionError(sessionId='%s', exception=%d, sysCode=%d, msg='%s')",
+        this, aSessionId.get(),
+        aException, aSystemCode, aMessage.get()));
+
  if (!mIsOpen) {
    NS_WARNING("Trying to use a dead GMP decrypter!");
    return false;
@ -272,6 +329,9 @@ GMPDecryptorParent::RecvKeyStatusChanged(const nsCString& aSessionId,
                                         InfallibleTArray<uint8_t>&& aKeyId,
                                         const GMPMediaKeyStatus& aStatus)
 {
+  LOGD(("GMPDecryptorParent[%p]::RecvKeyStatusChanged(sessionId='%s', keyId=%s, status=%d)",
+        this, aSessionId.get(), ToBase64(aKeyId).get(), aStatus));
+
  if (mIsOpen) {
    mCallback->KeyStatusChanged(aSessionId, aKeyId, aStatus);
  }
@ -281,6 +341,8 @@ GMPDecryptorParent::RecvKeyStatusChanged(const nsCString& aSessionId,
 bool
 GMPDecryptorParent::RecvSetCaps(const uint64_t& aCaps)
 {
+  LOGD(("GMPDecryptorParent[%p]::RecvSetCaps(caps=0x%llx)", this, aCaps));
+
  if (!mIsOpen) {
    NS_WARNING("Trying to use a dead GMP decrypter!");
    return false;
@ -294,6 +356,9 @@ GMPDecryptorParent::RecvDecrypted(const uint32_t& aId,
                                  const GMPErr& aErr,
                                  InfallibleTArray<uint8_t>&& aBuffer)
 {
+  LOGV(("GMPDecryptorParent[%p]::RecvDecrypted(id=%d, err=%d)",
+        this, aId, aErr));
+
  if (!mIsOpen) {
    NS_WARNING("Trying to use a dead GMP decrypter!");
    return false;
@ -305,6 +370,8 @@ GMPDecryptorParent::RecvDecrypted(const uint32_t& aId,
 bool
 GMPDecryptorParent::RecvShutdown()
 {
+  LOGD(("GMPDecryptorParent[%p]::RecvShutdown()", this));
+
  Shutdown();
  return true;
 }
@ -313,7 +380,9 @@ GMPDecryptorParent::RecvShutdown()
 void
 GMPDecryptorParent::Close()
 {
+  LOGD(("GMPDecryptorParent[%p]::Close()", this));
  MOZ_ASSERT(mGMPThread == NS_GetCurrentThread());
+
  // Consumer is done with us; we can shut down.  No more callbacks should
  // be made to mCallback. Note: do this before Shutdown()!
  mCallback = nullptr;
@ -328,6 +397,7 @@ GMPDecryptorParent::Close()
 void
 GMPDecryptorParent::Shutdown()
 {
+  LOGD(("GMPDecryptorParent[%p]::Shutdown()", this));
  MOZ_ASSERT(mGMPThread == NS_GetCurrentThread());

  if (mShuttingDown) {
@ -351,6 +421,8 @@ GMPDecryptorParent::Shutdown()
 void
 GMPDecryptorParent::ActorDestroy(ActorDestroyReason aWhy)
 {
+  LOGD(("GMPDecryptorParent[%p]::ActorDestroy(reason=%d)", this, aWhy));
+
  mIsOpen = false;
  mActorDestroyed = true;
  if (mCallback) {
@ -367,6 +439,8 @@ GMPDecryptorParent::ActorDestroy(ActorDestroyReason aWhy)
 bool
 GMPDecryptorParent::Recv__delete__()
 {
+  LOGD(("GMPDecryptorParent[%p]::Recv__delete__()", this));
+
  if (mPlugin) {
    mPlugin->DecryptorDestroyed(this);
    mPlugin = nullptr;
--- a/dom/media/gmp/GMPStorageParent.cpp
+++ b/dom/media/gmp/GMPStorageParent.cpp
@ -30,11 +30,6 @@ extern PRLogModuleInfo* GetGMPLog();
 #define LOGD(msg) MOZ_LOG(GetGMPLog(), mozilla::LogLevel::Debug, msg)
 #define LOG(level, msg) MOZ_LOG(GetGMPLog(), (level), msg)

-#ifdef __CLASS__
-#undef __CLASS__
-#endif
-#define __CLASS__ "GMPStorageParent"
-
 namespace gmp {

 // We store the records in files in the profile dir.
@ -165,7 +160,7 @@ public:
  {
    MOZ_ASSERT(!IsOpen(aRecordName));
    nsresult rv;
-    Record* record = nullptr; 
+    Record* record = nullptr;
    if (!mRecords.Get(aRecordName, &record)) {
      // New file.
      nsAutoString filename;
@ -254,7 +249,7 @@ public:
      return GMPClosedErr;
    }

-    Record* record = nullptr; 
+    Record* record = nullptr;
    mRecords.Get(aRecordName, &record);
    MOZ_ASSERT(record && !!record->mFileDesc); // IsOpen() guarantees this.

@ -581,6 +576,8 @@ GMPStorageParent::GMPStorageParent(const nsCString& aNodeId,
 nsresult
 GMPStorageParent::Init()
 {
+  LOGD(("GMPStorageParent[%p]::Init()", this));
+
  if (NS_WARN_IF(mNodeId.IsEmpty())) {
    return NS_ERROR_FAILURE;
  }
@ -611,6 +608,9 @@ GMPStorageParent::Init()
 bool
 GMPStorageParent::RecvOpen(const nsCString& aRecordName)
 {
+  LOGD(("GMPStorageParent[%p]::RecvOpen(record='%s')",
+       this, aRecordName.get()));
+
  if (mShutdown) {
    return false;
  }
@ -618,23 +618,30 @@ GMPStorageParent::RecvOpen(const nsCString& aRecordName)
  if (mNodeId.EqualsLiteral("null")) {
    // Refuse to open storage if the page is opened from local disk,
    // or shared across origin.
-    NS_WARNING("Refusing to open storage for null NodeId");
+    LOGD(("GMPStorageParent[%p]::RecvOpen(record='%s') failed; null nodeId",
+          this, aRecordName.get()));
    unused << SendOpenComplete(aRecordName, GMPGenericErr);
    return true;
  }

  if (aRecordName.IsEmpty()) {
+    LOGD(("GMPStorageParent[%p]::RecvOpen(record='%s') failed; record name empty",
+          this, aRecordName.get()));
    unused << SendOpenComplete(aRecordName, GMPGenericErr);
    return true;
  }

  if (mStorage->IsOpen(aRecordName)) {
+    LOGD(("GMPStorageParent[%p]::RecvOpen(record='%s') failed; record in use",
+          this, aRecordName.get()));
    unused << SendOpenComplete(aRecordName, GMPRecordInUse);
    return true;
  }

  auto err = mStorage->Open(aRecordName);
  MOZ_ASSERT(GMP_FAILED(err) || mStorage->IsOpen(aRecordName));
+  LOGD(("GMPStorageParent[%p]::RecvOpen(record='%s') complete; rv=%d",
+        this, aRecordName.get(), err));
  unused << SendOpenComplete(aRecordName, err);

  return true;
@ -643,7 +650,8 @@ GMPStorageParent::RecvOpen(const nsCString& aRecordName)
 bool
 GMPStorageParent::RecvRead(const nsCString& aRecordName)
 {
-  LOGD(("%s::%s: %p record=%s", __CLASS__, __FUNCTION__, this, aRecordName.get()));
+  LOGD(("GMPStorageParent[%p]::RecvRead(record='%s')",
+       this, aRecordName.get()));

  if (mShutdown) {
    return false;
@ -651,9 +659,14 @@ GMPStorageParent::RecvRead(const nsCString& aRecordName)

  nsTArray<uint8_t> data;
  if (!mStorage->IsOpen(aRecordName)) {
+    LOGD(("GMPStorageParent[%p]::RecvRead(record='%s') failed; record not open",
+         this, aRecordName.get()));
    unused << SendReadComplete(aRecordName, GMPClosedErr, data);
  } else {
-    unused << SendReadComplete(aRecordName, mStorage->Read(aRecordName, data), data);
+    GMPErr rv = mStorage->Read(aRecordName, data);
+    LOGD(("GMPStorageParent[%p]::RecvRead(record='%s') read %d bytes rv=%d",
+      this, aRecordName.get(), data.Length(), rv));
+    unused << SendReadComplete(aRecordName, rv, data);
  }

  return true;
@ -663,23 +676,32 @@ bool
 GMPStorageParent::RecvWrite(const nsCString& aRecordName,
                            InfallibleTArray<uint8_t>&& aBytes)
 {
-  LOGD(("%s::%s: %p record=%s", __CLASS__, __FUNCTION__, this, aRecordName.get()));
+  LOGD(("GMPStorageParent[%p]::RecvWrite(record='%s') %d bytes",
+        this, aRecordName.get(), aBytes.Length()));

  if (mShutdown) {
    return false;
  }

  if (!mStorage->IsOpen(aRecordName)) {
+    LOGD(("GMPStorageParent[%p]::RecvWrite(record='%s') failed record not open",
+          this, aRecordName.get()));
    unused << SendWriteComplete(aRecordName, GMPClosedErr);
    return true;
  }

  if (aBytes.Length() > GMP_MAX_RECORD_SIZE) {
+    LOGD(("GMPStorageParent[%p]::RecvWrite(record='%s') failed record too big",
+          this, aRecordName.get()));
    unused << SendWriteComplete(aRecordName, GMPQuotaExceededErr);
    return true;
  }

-  unused << SendWriteComplete(aRecordName, mStorage->Write(aRecordName, aBytes));
+  GMPErr rv = mStorage->Write(aRecordName, aBytes);
+  LOGD(("GMPStorageParent[%p]::RecvWrite(record='%s') write complete rv=%d",
+        this, aRecordName.get(), rv));
+
+  unused << SendWriteComplete(aRecordName, rv);

  return true;
 }
@ -687,14 +709,16 @@ GMPStorageParent::RecvWrite(const nsCString& aRecordName,
 bool
 GMPStorageParent::RecvGetRecordNames()
 {
-  LOGD(("%s::%s: %p", __CLASS__, __FUNCTION__, this));
-
  if (mShutdown) {
    return true;
  }

  nsTArray<nsCString> recordNames;
  GMPErr status = mStorage->GetRecordNames(recordNames);
+
+  LOGD(("GMPStorageParent[%p]::RecvGetRecordNames() status=%d numRecords=%d",
+        this, status, recordNames.Length()));
+
  unused << SendRecordNames(recordNames, status);

  return true;
@ -703,7 +727,8 @@ GMPStorageParent::RecvGetRecordNames()
 bool
 GMPStorageParent::RecvClose(const nsCString& aRecordName)
 {
-  LOGD(("%s::%s: %p record=%s", __CLASS__, __FUNCTION__, this, aRecordName.get()));
+  LOGD(("GMPStorageParent[%p]::RecvClose(record='%s')",
+        this, aRecordName.get()));

  if (mShutdown) {
    return true;
@ -717,14 +742,14 @@ GMPStorageParent::RecvClose(const nsCString& aRecordName)
 void
 GMPStorageParent::ActorDestroy(ActorDestroyReason aWhy)
 {
-  LOGD(("%s::%s: %p", __CLASS__, __FUNCTION__, this));
+  LOGD(("GMPStorageParent[%p]::ActorDestroy(reason=%d)", this, aWhy));
  Shutdown();
 }

 void
 GMPStorageParent::Shutdown()
 {
-  LOGD(("%s::%s: %p", __CLASS__, __FUNCTION__, this));
+  LOGD(("GMPStorageParent[%p]::Shutdown()", this));

  if (mShutdown) {
    return;
--- a/dom/media/gmp/GMPUtils.cpp
+++ b/dom/media/gmp/GMPUtils.cpp
@ -10,6 +10,7 @@
 #include "nsCOMPtr.h"
 #include "nsLiteralString.h"
 #include "nsCRTGlue.h"
+#include "mozilla/Base64.h"

 namespace mozilla {

@ -50,4 +51,17 @@ SplitAt(const char* aDelims,
  }
 }

+nsCString
+ToBase64(const nsTArray<uint8_t>& aBytes)
+{
+  nsAutoCString base64;
+  nsDependentCSubstring raw(reinterpret_cast<const char*>(aBytes.Elements()),
+                            aBytes.Length());
+  nsresult rv = Base64Encode(raw, base64);
+  if (NS_WARN_IF(NS_FAILED(rv))) {
+    return NS_LITERAL_CSTRING("[Base64EncodeFailed]");
+  }
+  return base64;
+}
+
 } // namespace mozilla
--- a/dom/media/gmp/GMPUtils.h
+++ b/dom/media/gmp/GMPUtils.h
@ -34,6 +34,9 @@ SplitAt(const char* aDelims,
        const nsACString& aInput,
        nsTArray<nsCString>& aOutTokens);

+nsCString
+ToBase64(const nsTArray<uint8_t>& aBytes);
+
 } // namespace mozilla

 #endif
--- a/dom/media/gmp/GMPVideoDecoderParent.cpp
+++ b/dom/media/gmp/GMPVideoDecoderParent.cpp
@ -23,6 +23,7 @@ namespace mozilla {

 extern PRLogModuleInfo* GetGMPLog();

+#define LOGV(msg) MOZ_LOG(GetGMPLog(), mozilla::LogLevel::Verbose, msg)
 #define LOGD(msg) MOZ_LOG(GetGMPLog(), mozilla::LogLevel::Debug, msg)
 #define LOG(level, msg) MOZ_LOG(GetGMPLog(), (level), msg)

@ -67,7 +68,7 @@ GMPVideoDecoderParent::Host()
 void
 GMPVideoDecoderParent::Close()
 {
-  LOGD(("%s: %p", __FUNCTION__, this));
+  LOGD(("GMPVideoDecoderParent[%p]::Close()", this));
  MOZ_ASSERT(!mPlugin || mPlugin->GMPThread() == NS_GetCurrentThread());

  // Ensure if we've received a Close while waiting for a ResetComplete
@ -92,6 +93,8 @@ GMPVideoDecoderParent::InitDecode(const GMPVideoCodec& aCodecSettings,
                                  GMPVideoDecoderCallbackProxy* aCallback,
                                  int32_t aCoreCount)
 {
+  LOGD(("GMPVideoDecoderParent[%p]::InitDecode()", this));
+
  if (mActorDestroyed) {
    NS_WARNING("Trying to use a destroyed GMP video decoder!");
    return NS_ERROR_FAILURE;
@ -123,6 +126,10 @@ GMPVideoDecoderParent::Decode(GMPUniquePtr<GMPVideoEncodedFrame> aInputFrame,
                              const nsTArray<uint8_t>& aCodecSpecificInfo,
                              int64_t aRenderTimeMs)
 {
+  LOGV(("GMPVideoDecoderParent[%p]::Decode() timestamp=%lld keyframe=%d",
+        this, aInputFrame->TimeStamp(),
+        aInputFrame->FrameType() == kGMPKeyFrame));
+
  if (!mIsOpen) {
    NS_WARNING("Trying to use an dead GMP video decoder");
    return NS_ERROR_FAILURE;
@ -158,6 +165,8 @@ GMPVideoDecoderParent::Decode(GMPUniquePtr<GMPVideoEncodedFrame> aInputFrame,
 nsresult
 GMPVideoDecoderParent::Reset()
 {
+  LOGD(("GMPVideoDecoderParent[%p]::Reset()", this));
+
  if (!mIsOpen) {
    NS_WARNING("Trying to use an dead GMP video decoder");
    return NS_ERROR_FAILURE;
@ -178,6 +187,8 @@ GMPVideoDecoderParent::Reset()
 nsresult
 GMPVideoDecoderParent::Drain()
 {
+  LOGD(("GMPVideoDecoderParent[%p]::Drain()", this));
+
  if (!mIsOpen) {
    NS_WARNING("Trying to use an dead GMP video decoder");
    return NS_ERROR_FAILURE;
@ -211,7 +222,7 @@ GMPVideoDecoderParent::GetDisplayName() const
 nsresult
 GMPVideoDecoderParent::Shutdown()
 {
-  LOGD(("%s: %p", __FUNCTION__, this));
+  LOGD(("GMPVideoDecoderParent[%p]::Shutdown()", this));
  MOZ_ASSERT(!mPlugin || mPlugin->GMPThread() == NS_GetCurrentThread());

  if (mShuttingDown) {
@ -242,6 +253,8 @@ GMPVideoDecoderParent::Shutdown()
 void
 GMPVideoDecoderParent::ActorDestroy(ActorDestroyReason aWhy)
 {
+  LOGD(("GMPVideoDecoderParent[%p]::ActorDestroy reason=%d", this, aWhy));
+
  mIsOpen = false;
  mActorDestroyed = true;
  mVideoHost.DoneWithAPI();
@ -267,12 +280,17 @@ GMPVideoDecoderParent::ActorDestroy(ActorDestroyReason aWhy)
 bool
 GMPVideoDecoderParent::RecvDecoded(const GMPVideoi420FrameData& aDecodedFrame)
 {
+  LOGV(("GMPVideoDecoderParent[%p]::RecvDecoded() timestamp=%lld",
+        this, aDecodedFrame.mTimestamp()));
+
  if (!mCallback) {
    return false;
  }

  if (!GMPVideoi420FrameImpl::CheckFrameData(aDecodedFrame)) {
-    LOG(LogLevel::Error, ("%s: Decoded frame corrupt, ignoring", __FUNCTION__));
+    LOG(LogLevel::Error,
+      ("GMPVideoDecoderParent[%p]::RecvDecoded() "
+       "timestamp=%lld decoded frame corrupt, ignoring"));
    return false;
  }
  auto f = new GMPVideoi420FrameImpl(aDecodedFrame, &mVideoHost);
@ -312,6 +330,8 @@ GMPVideoDecoderParent::RecvReceivedDecodedFrame(const uint64_t& aPictureId)
 bool
 GMPVideoDecoderParent::RecvInputDataExhausted()
 {
+  LOGV(("GMPVideoDecoderParent[%p]::RecvInputDataExhausted()", this));
+
  if (!mCallback) {
    return false;
  }
@ -325,6 +345,8 @@ GMPVideoDecoderParent::RecvInputDataExhausted()
 bool
 GMPVideoDecoderParent::RecvDrainComplete()
 {
+  LOGD(("GMPVideoDecoderParent[%p]::RecvDrainComplete()", this));
+
  if (!mCallback) {
    return false;
  }
@ -343,6 +365,8 @@ GMPVideoDecoderParent::RecvDrainComplete()
 bool
 GMPVideoDecoderParent::RecvResetComplete()
 {
+  LOGD(("GMPVideoDecoderParent[%p]::RecvResetComplete()", this));
+
  if (!mCallback) {
    return false;
  }
@ -361,6 +385,8 @@ GMPVideoDecoderParent::RecvResetComplete()
 bool
 GMPVideoDecoderParent::RecvError(const GMPErr& aError)
 {
+  LOGD(("GMPVideoDecoderParent[%p]::RecvError(error=%d)", this, aError));
+
  if (!mCallback) {
    return false;
  }
@ -379,6 +405,8 @@ GMPVideoDecoderParent::RecvError(const GMPErr& aError)
 bool
 GMPVideoDecoderParent::RecvShutdown()
 {
+  LOGD(("GMPVideoDecoderParent[%p]::RecvShutdown()", this));
+
  Shutdown();
  return true;
 }
@ -415,6 +443,8 @@ GMPVideoDecoderParent::AnswerNeedShmem(const uint32_t& aFrameBufferSize,
 bool
 GMPVideoDecoderParent::Recv__delete__()
 {
+  LOGD(("GMPVideoDecoderParent[%p]::Recv__delete__()", this));
+
  if (mPlugin) {
    // Ignore any return code. It is OK for this to fail without killing the process.
    mPlugin->VideoDecoderDestroyed(this);
@ -427,6 +457,8 @@ GMPVideoDecoderParent::Recv__delete__()
 void
 GMPVideoDecoderParent::UnblockResetAndDrain()
 {
+  LOGD(("GMPVideoDecoderParent[%p]::UnblockResetAndDrain()", this));
+
  if (!mCallback) {
    MOZ_ASSERT(!mIsAwaitingResetComplete);
    MOZ_ASSERT(!mIsAwaitingDrainComplete);