Bug 1042765 - Better logging for GMP plugins r=cpearce

content/media/gmp/GMPParent.cpp

@@ -4,6 +4,7 @@
  * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
 
 #include "GMPParent.h"
+#include "prlog.h"
 #include "nsComponentManagerUtils.h"
 #include "nsComponentManagerUtils.h"
 #include "nsIInputStream.h"
@@ -26,6 +27,26 @@ using CrashReporter::GetIDFromMinidump;
 #endif
 
 namespace mozilla {
+
+#ifdef LOG
+#undef LOG
+#endif
+
+#ifdef PR_LOGGING
+extern PRLogModuleInfo* GetGMPLog();
+
+#define LOGD(msg) PR_LOG(GetGMPLog(), PR_LOG_DEBUG, msg)
+#define LOG(level, msg) PR_LOG(GetGMPLog(), (level), msg)
+#else
+#define LOGD(msg)
+#define LOG(level, msg)
+#endif
+
+#ifdef __CLASS__
+#undef __CLASS__
+#endif
+#define __CLASS__ "GMPParent"
+
 namespace gmp {
 
 GMPParent::GMPParent()
@@ -54,6 +75,8 @@ GMPParent::Init(nsIFile* aPluginDir)
   if (NS_FAILED(rv)) {
     return rv;
   }
+  LOGD(("%s::%s: %p for %s", __CLASS__, __FUNCTION__, this, 
+       NS_LossyConvertUTF16toASCII(leafname).get()));
 
   MOZ_ASSERT(leafname.Length() > 4);
   mName = Substring(leafname, 4);
@@ -72,6 +95,7 @@ GMPParent::LoadProcess()
   if (NS_FAILED(mDirectory->GetNativePath(path))) {
     return NS_ERROR_FAILURE;
   }
+  LOGD(("%s::%s: %p for %s", __CLASS__, __FUNCTION__, this, path.get()));
 
   if (!mProcess) {
     mProcess = new GMPProcessParent(path.get());
@@ -111,6 +135,7 @@ GMPParent::CloseIfUnused()
 void
 GMPParent::CloseActive(bool aDieWhenUnloaded)
 {
+  LOGD(("%s::%s: %p state %d", __CLASS__, __FUNCTION__, this, mState));
   if (aDieWhenUnloaded) {
     mDeleteProcessOnUnload = true; // don't allow this to go back...
   }
@@ -137,6 +162,7 @@ GMPParent::CloseActive(bool aDieWhenUnloaded)
 void
 GMPParent::Shutdown()
 {
+  LOGD(("%s::%s: %p", __CLASS__, __FUNCTION__, this));
   MOZ_ASSERT(GMPThread() == NS_GetCurrentThread());
 
   MOZ_ASSERT(mVideoDecoders.IsEmpty() && mVideoEncoders.IsEmpty());
@@ -158,6 +184,7 @@ GMPParent::Shutdown()
 void
 GMPParent::DeleteProcess()
 {
+  LOGD(("%s::%s: %p", __CLASS__, __FUNCTION__, this));
   Close();
   mProcess->Delete();
   mProcess = nullptr;
@@ -352,10 +379,10 @@ GMPNotifyObservers(nsAString& aData)
   }
 }
 #endif
-
 void
 GMPParent::ActorDestroy(ActorDestroyReason aWhy)
 {
+  LOGD(("%s::%s: %p (%d)", __CLASS__, __FUNCTION__, this, (int) aWhy));
 #ifdef MOZ_CRASHREPORTER
   if (AbnormalShutdown == aWhy) {
     nsString dumpID;

content/media/gmp/GMPService.cpp

@@ -4,6 +4,7 @@
  * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
 
 #include "GMPService.h"
+#include "prlog.h"
 #include "GMPParent.h"
 #include "GMPVideoDecoderParent.h"
 #include "nsIObserverService.h"
@@ -17,6 +18,28 @@
 #include "mozilla/unused.h"
 
 namespace mozilla {
+
+#ifdef LOG
+#undef LOG
+#endif
+
+#ifdef PR_LOGGING
+PRLogModuleInfo*
+GetGMPLog()
+{
+  static PRLogModuleInfo *sLog;
+  if (!sLog)
+    sLog = PR_NewLogModule("GMP");
+  return sLog;
+}
+
+#define LOGD(msg) PR_LOG(GetGMPLog(), PR_LOG_DEBUG, msg)
+#define LOG(level, msg) PR_LOG(GetGMPLog(), (level), msg)
+#else
+#define LOGD(msg)
+#define LOG(leve1, msg)
+#endif
+
 namespace gmp {
 
 static StaticRefPtr<GeckoMediaPluginService> sSingletonService;
@@ -203,10 +226,15 @@ GeckoMediaPluginService::GetGMPVideoDecoder(nsTArray<nsCString>* aTags,
   nsRefPtr<GMPParent> gmp = SelectPluginForAPI(aOrigin,
                                                NS_LITERAL_CSTRING("decode-video"),
                                                *aTags);
+#ifdef PR_LOGGING
+  nsCString api = (*aTags)[0];
+  LOGD(("%s: %p returning %p for api %s", __FUNCTION__, (void *)this, (void *)gmp, api.get()));
+#endif
   if (!gmp) {
     return NS_ERROR_FAILURE;
   }
 
+
   GMPVideoDecoderParent* gmpVDP;
   nsresult rv = gmp->GetGMPVideoDecoder(&gmpVDP);
   if (NS_FAILED(rv)) {
@@ -237,6 +265,10 @@ GeckoMediaPluginService::GetGMPVideoEncoder(nsTArray<nsCString>* aTags,
   nsRefPtr<GMPParent> gmp = SelectPluginForAPI(aOrigin,
                                                NS_LITERAL_CSTRING("encode-video"),
                                                *aTags);
+#ifdef PR_LOGGING
+  nsCString api = (*aTags)[0];
+  LOGD(("%s: %p returning %p for api %s", __FUNCTION__, (void *)this, (void *)gmp, api.get()));
+#endif
   if (!gmp) {
     return NS_ERROR_FAILURE;
   }

content/media/gmp/GMPVideoDecoderParent.cpp

@@ -4,14 +4,14 @@
  * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
 
 #include "GMPVideoDecoderParent.h"
+#include "prlog.h"
+#include "mozilla/unused.h"
+#include "nsAutoRef.h"
+#include "nsThreadUtils.h"
 #include "GMPVideoEncodedFrameImpl.h"
 #include "GMPVideoi420FrameImpl.h"
 #include "GMPParent.h"
-#include <stdio.h>
-#include "mozilla/unused.h"
 #include "GMPMessageUtils.h"
-#include "nsAutoRef.h"
-#include "nsThreadUtils.h"
 #include "mozilla/gmp/GMPTypes.h"
 
 template <>
@@ -22,6 +22,21 @@ public:
 };
 
 namespace mozilla {
+
+#ifdef LOG
+#undef LOG
+#endif
+
+#ifdef PR_LOGGING
+extern PRLogModuleInfo* GetGMPLog();
+
+#define LOGD(msg) PR_LOG(GetGMPLog(), PR_LOG_DEBUG, msg)
+#define LOG(level, msg) PR_LOG(GetGMPLog(), (level), msg)
+#else
+#define LOGD(msg)
+#define LOG(level, msg)
+#endif
+
 namespace gmp {
 
 // States:
@@ -57,6 +72,7 @@ GMPVideoDecoderParent::Host()
 void
 GMPVideoDecoderParent::Close()
 {
+  LOGD(("%s: %p", __FUNCTION__, this));
   MOZ_ASSERT(mPlugin->GMPThread() == NS_GetCurrentThread());
   // Consumer is done with us; we can shut down.  No more callbacks should
   // be made to mCallback.  Note: do this before Shutdown()!
@@ -175,6 +191,7 @@ GMPVideoDecoderParent::Drain()
 nsresult
 GMPVideoDecoderParent::Shutdown()
 {
+  LOGD(("%s: %p", __FUNCTION__, this));
   MOZ_ASSERT(mPlugin->GMPThread() == NS_GetCurrentThread());
 
   // Notify client we're gone!  Won't occur after Close()
@@ -330,6 +347,8 @@ GMPVideoDecoderParent::AnswerNeedShmem(const uint32_t& aFrameBufferSize,
                                                 aFrameBufferSize,
                                                 ipc::SharedMemory::TYPE_BASIC, &mem))
   {
+    LOG(PR_LOG_ERROR, ("%s: Failed to get a shared mem buffer for Child! size %u",
+                       __FUNCTION__, aFrameBufferSize));
     return false;
   }
   *aMem = mem;

content/media/gmp/GMPVideoEncoderParent.cpp

@@ -4,9 +4,9 @@
  * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
 
 #include "GMPVideoEncoderParent.h"
+#include "prlog.h"
 #include "GMPVideoi420FrameImpl.h"
 #include "GMPVideoEncodedFrameImpl.h"
-#include <stdio.h>
 #include "mozilla/unused.h"
 #include "GMPMessageUtils.h"
 #include "nsAutoRef.h"
@@ -22,6 +22,26 @@ public:
 };
 
 namespace mozilla {
+
+#ifdef LOG
+#undef LOG
+#endif
+
+#ifdef PR_LOGGING
+extern PRLogModuleInfo* GetGMPLog();
+
+#define LOGD(msg) PR_LOG(GetGMPLog(), PR_LOG_DEBUG, msg)
+#define LOG(level, msg) PR_LOG(GetGMPLog(), (level), msg)
+#else
+#define LOGD(msg)
+#define LOG(level, msg)
+#endif
+
+#ifdef __CLASS__
+#undef __CLASS__
+#endif
+#define __CLASS__ "GMPVideoEncoderParent"
+
 namespace gmp {
 
 // States:
@@ -57,6 +77,7 @@ GMPVideoEncoderParent::Host()
 void
 GMPVideoEncoderParent::Close()
 {
+  LOGD(("%s::%s: %p", __CLASS__, __FUNCTION__, this));
   MOZ_ASSERT(mPlugin->GMPThread() == NS_GetCurrentThread());
   // Consumer is done with us; we can shut down.  No more callbacks should
   // be made to mCallback.  Note: do this before Shutdown()!
@@ -76,6 +97,7 @@ GMPVideoEncoderParent::InitEncode(const GMPVideoCodec& aCodecSettings,
                                   int32_t aNumberOfCores,
                                   uint32_t aMaxPayloadSize)
 {
+  LOGD(("%s::%s: %p", __CLASS__, __FUNCTION__, this));
   if (mIsOpen) {
     NS_WARNING("Trying to re-init an in-use GMP video encoder!");
     return GMPGenericErr;;
@@ -192,6 +214,7 @@ GMPVideoEncoderParent::SetPeriodicKeyFrames(bool aEnable)
 void
 GMPVideoEncoderParent::Shutdown()
 {
+  LOGD(("%s::%s: %p", __CLASS__, __FUNCTION__, this));
   MOZ_ASSERT(mPlugin->GMPThread() == NS_GetCurrentThread());
 
   // Notify client we're gone!  Won't occur after Close()
@@ -211,6 +234,7 @@ GMPVideoEncoderParent::Shutdown()
 void
 GMPVideoEncoderParent::ActorDestroy(ActorDestroyReason aWhy)
 {
+  LOGD(("%s::%s: %p (%d)", __CLASS__, __FUNCTION__, this, (int) aWhy));
   mIsOpen = false;
   if (mCallback) {
     // May call Close() (and Shutdown()) immediately or with a delay
@@ -282,6 +306,8 @@ GMPVideoEncoderParent::AnswerNeedShmem(const uint32_t& aEncodedBufferSize,
                                                 aEncodedBufferSize,
                                                 ipc::SharedMemory::TYPE_BASIC, &mem))
   {
+    LOG(PR_LOG_ERROR, ("%s::%s: Failed to get a shared mem buffer for Child! size %u",
+                       __CLASS__, __FUNCTION__, aEncodedBufferSize));
     return false;
   }
   *aMem = mem;

media/webrtc/signaling/src/media-conduit/WebrtcGmpVideoCodec.cpp

@@ -31,6 +31,10 @@ namespace mozilla {
 #endif
 
 #ifdef PR_LOGGING
+#ifdef MOZILLA_INTERNAL_API
+extern PRLogModuleInfo* GetGMPLog();
+#else
+// For CPP unit tests
 PRLogModuleInfo*
 GetGMPLog()
 {
@@ -39,6 +43,7 @@ GetGMPLog()
     sLog = PR_NewLogModule("GMP");
   return sLog;
 }
+#endif
 #define LOGD(msg) PR_LOG(GetGMPLog(), PR_LOG_DEBUG, msg)
 #define LOG(level, msg) PR_LOG(GetGMPLog(), (level), msg)
 #else
@@ -301,6 +306,7 @@ WebrtcGmpVideoEncoder::RegisterEncodeCompleteCallback(webrtc::EncodedImageCallba
 int32_t
 WebrtcGmpVideoEncoder::Release()
 {
+  LOGD(("GMP Released:"));
   // Note: we only use SyncRunnables to access mGMP
   // Callbacks may occur at any time until we call Close (or receive
   // Terminated()), so call Close here synchronously.
@@ -355,6 +361,7 @@ WebrtcGmpVideoEncoder::SetRates_g(uint32_t aNewBitRate, uint32_t aFrameRate)
 void
 WebrtcGmpVideoEncoder::Terminated()
 {
+  LOGD(("GMP Encoder Terminated: %p", (void *)this));
   // We need to drop our reference to this
   mGMP->Close();
   mGMP = nullptr;
@@ -637,6 +644,7 @@ WebrtcGmpVideoDecoder::Reset()
 void
 WebrtcGmpVideoDecoder::Terminated()
 {
+  LOGD(("GMP Decoder Terminated: %p", (void *)this));
   mGMP->Close();
   mGMP = nullptr;
   // Could now notify that it's dead