Bug 1318965 - Improves the logging in Clearkey r?cpearce draft
authorJay Harris <jharris@mozilla.com>
Wed, 18 Jan 2017 14:49:58 +1300
changeset 462865 432ab764dcec12da295294615e8024a9fdfe7662
parent 462853 783430c2d92018d686ddd8779bea1939936c618a
child 542505 5104b3267cc1739bff95493bf18888df940c39dc
push id41875
push userbmo:jharris@mozilla.com
push dateWed, 18 Jan 2017 03:02:17 +0000
reviewerscpearce
bugs1318965
milestone53.0a1
Bug 1318965 - Improves the logging in Clearkey r?cpearce MozReview-Commit-ID: DTQAI7ffMm7
media/gmp-clearkey/0.1/ClearKeySessionManager.cpp
media/gmp-clearkey/0.1/VideoDecoder.cpp
--- a/media/gmp-clearkey/0.1/ClearKeySessionManager.cpp
+++ b/media/gmp-clearkey/0.1/ClearKeySessionManager.cpp
@@ -72,45 +72,46 @@ ClearKeySessionManager::Init(bool aDisti
 
 void
 ClearKeySessionManager::CreateSession(uint32_t aPromiseId,
                                       InitDataType aInitDataType,
                                       const uint8_t* aInitData,
                                       uint32_t aInitDataSize,
                                       SessionType aSessionType)
 {
+  CK_LOGD("ClearKeySessionManager::CreateSession type:%u", aInitDataType);
+
   // Copy the init data so it is correctly captured by the lambda
   vector<uint8_t> initData(aInitData, aInitData + aInitDataSize);
 
   RefPtr<ClearKeySessionManager> self(this);
   function<void()> deferrer =
     [self, aPromiseId, aInitDataType, initData, aSessionType] ()
   {
     self->CreateSession(aPromiseId,
                         aInitDataType,
                         initData.data(),
                         initData.size(),
                         aSessionType);
   };
 
   // If we haven't loaded, don't do this yet
   if (MaybeDeferTillInitialized(deferrer)) {
+    CK_LOGD("Deferring CreateSession");
     return;
   }
 
-  CK_LOGD("ClearKeySessionManager::CreateSession type:%s", aInitDataType);
-
   CK_LOGARRAY("ClearKeySessionManager::CreateSession initdata: ",
               aInitData,
               aInitDataSize);
 
   // If 'DecryptingComplete' has been called mHost will be null so we can't
   // won't be able to resolve our promise
   if (!mHost) {
-    CK_LOGD("ClearKeySessionManager::CreateSession: mHost is nullptr")
+    CK_LOGD("ClearKeySessionManager::CreateSession: mHost is nullptr");
     return;
   }
 
   // initDataType must be "cenc", "keyids", or "webm".
   if (aInitDataType != InitDataType::kCenc &&
       aInitDataType != InitDataType::kKeyIds &&
       aInitDataType != InitDataType::kWebM) {
 
@@ -181,34 +182,35 @@ ClearKeySessionManager::CreateSession(ui
                           0);
 }
 
 void
 ClearKeySessionManager::LoadSession(uint32_t aPromiseId,
                                     const char* aSessionId,
                                     uint32_t aSessionIdLength)
 {
+  CK_LOGD("ClearKeySessionManager::LoadSession");
+
   // Copy the sessionId into a string so the lambda captures it properly.
   string sessionId(aSessionId, aSessionId + aSessionIdLength);
 
   // Hold a reference to the SessionManager so that it isn't released before
   // we try to use it.
   RefPtr<ClearKeySessionManager> self(this);
   function<void()> deferrer =
     [self, aPromiseId, sessionId] ()
   {
     self->LoadSession(aPromiseId, sessionId.data(), sessionId.size());
   };
 
   if (MaybeDeferTillInitialized(deferrer)) {
+    CK_LOGD("Deferring LoadSession");
     return;
   }
 
-  CK_LOGD("ClearKeySessionManager::LoadSession");
-
   // If the SessionManager has been shutdown mHost will be null and we won't
   // be able to resolve the promise.
   if (!mHost) {
     return;
   }
 
   if (!ClearKeyUtils::IsValidSessionId(aSessionId, aSessionIdLength)) {
     mHost->OnResolveNewSessionPromise(aPromiseId, nullptr, 0);
@@ -310,16 +312,18 @@ ClearKeySessionManager::PersistentSessio
 
 void
 ClearKeySessionManager::UpdateSession(uint32_t aPromiseId,
                                       const char* aSessionId,
                                       uint32_t aSessionIdLength,
                                       const uint8_t* aResponse,
                                       uint32_t aResponseSize)
 {
+  CK_LOGD("ClearKeySessionManager::UpdateSession");
+
   // Copy the method arguments so we can capture them in the lambda
   string sessionId(aSessionId, aSessionId + aSessionIdLength);
   vector<uint8_t> response(aResponse, aResponse + aResponseSize);
 
   // Hold  a reference to the SessionManager so it isn't released before we
   // callback.
   RefPtr<ClearKeySessionManager> self(this);
   function<void()> deferrer =
@@ -329,26 +333,26 @@ ClearKeySessionManager::UpdateSession(ui
                         sessionId.data(),
                         sessionId.size(),
                         response.data(),
                         response.size());
   };
 
   // If we haven't fully loaded, defer calling this method
   if (MaybeDeferTillInitialized(deferrer)) {
+    CK_LOGD("Deferring LoadSession");
     return;
   }
 
   // Make sure the SessionManager has not been shutdown before we try and
   // resolve any promises.
   if (!mHost) {
     return;
   }
 
-  CK_LOGD("ClearKeySessionManager::UpdateSession");
   CK_LOGD("Updating session: %s", sessionId.c_str());
 
   auto itr = mSessions.find(sessionId);
   if (itr == mSessions.end() || !(itr->second)) {
     CK_LOGW("ClearKey CDM couldn't resolve session ID in UpdateSession.");
     CK_LOGD("Unable to find session: %s", sessionId.c_str());
     mHost->OnRejectPromise(aPromiseId,
                            Error::kInvalidAccessError,
@@ -464,34 +468,35 @@ ClearKeySessionManager::Serialize(const 
   }
 }
 
 void
 ClearKeySessionManager::CloseSession(uint32_t aPromiseId,
                                      const char* aSessionId,
                                      uint32_t aSessionIdLength)
 {
+  CK_LOGD("ClearKeySessionManager::CloseSession");
+
   // Copy the sessionId into a string so we capture it properly.
   string sessionId(aSessionId, aSessionId + aSessionIdLength);
   // Hold a reference to the session manager, so it doesn't get deleted
   // before we need to use it.
   RefPtr<ClearKeySessionManager> self(this);
   function<void()> deferrer =
     [self, aPromiseId, sessionId] ()
   {
     self->CloseSession(aPromiseId, sessionId.data(), sessionId.size());
   };
 
   // If we haven't loaded, call this method later.
   if (MaybeDeferTillInitialized(deferrer)) {
+    CK_LOGD("Deferring CloseSession");
     return;
   }
 
-  CK_LOGD("ClearKeySessionManager::CloseSession");
-
   // If DecryptingComplete has been called mHost will be null and we won't
   // be able to resolve our promise.
   if (!mHost) {
     return;
   }
 
   auto itr = mSessions.find(sessionId);
   if (itr == mSessions.end()) {
@@ -521,40 +526,42 @@ ClearKeySessionManager::ClearInMemorySes
   delete aSession;
 }
 
 void
 ClearKeySessionManager::RemoveSession(uint32_t aPromiseId,
                                       const char* aSessionId,
                                       uint32_t aSessionIdLength)
 {
+  CK_LOGD("ClearKeySessionManager::RemoveSession");
+
   // Copy the sessionId into a string so it can be captured for the lambda.
   string sessionId(aSessionId, aSessionId + aSessionIdLength);
 
   // Hold a reference to the SessionManager, so it isn't released before we
   // try and use it.
   RefPtr<ClearKeySessionManager> self(this);
   function<void()> deferrer =
     [self, aPromiseId, sessionId] ()
   {
     self->RemoveSession(aPromiseId, sessionId.data(), sessionId.size());
   };
 
   // If we haven't fully loaded, defer calling this method.
   if (MaybeDeferTillInitialized(deferrer)) {
+    CK_LOGD("Deferring RemoveSession");
     return;
   }
 
   // Check that the SessionManager has not been shutdown before we try and
   // resolve any promises.
   if (!mHost) {
     return;
   }
 
-  CK_LOGD("ClearKeySessionManager::RemoveSession");
   auto itr = mSessions.find(sessionId);
   if (itr == mSessions.end()) {
     CK_LOGW("ClearKey CDM couldn't remove non-existent session.");
 
     mHost->OnRejectPromise(aPromiseId,
                            Error::kInvalidAccessError,
                            0,
                            nullptr,
--- a/media/gmp-clearkey/0.1/VideoDecoder.cpp
+++ b/media/gmp-clearkey/0.1/VideoDecoder.cpp
@@ -25,60 +25,64 @@
 
 using namespace wmf;
 using namespace cdm;
 
 VideoDecoder::VideoDecoder(Host_8 *aHost)
   : mHost(aHost)
   , mHasShutdown(false)
 {
+  CK_LOGD("VideoDecoder created");
+
   // We drop the ref in DecodingComplete().
   AddRef();
 
   mDecoder = new WMFH264Decoder();
 
   uint32_t cores = std::max(1u, std::thread::hardware_concurrency());
   HRESULT hr = mDecoder->Init(cores);
 }
 
 VideoDecoder::~VideoDecoder()
 {
-
+  CK_LOGD("VideoDecoder destroyed");
 }
 
 Status
 VideoDecoder::InitDecode(const VideoDecoderConfig& aConfig)
 {
+  CK_LOGD("VideoDecoder::InitDecode");
+
   if (!mDecoder) {
     CK_LOGD("VideoDecoder::InitDecode failed to init WMFH264Decoder");
 
     return Status::kDecodeError;
   }
 
   return Status::kSuccess;
 }
 
 Status
 VideoDecoder::Decode(const InputBuffer& aInputBuffer, VideoFrame* aVideoFrame)
 {
+  CK_LOGD("VideoDecoder::Decode");
   // If the input buffer we have been passed has a null buffer, it means we
   // should drain.
   if (!aInputBuffer.data) {
     // This will drain the decoder until there are no frames left to drain,
     // whereupon it will return 'NeedsMoreData'.
-    CK_LOGD("Input buffer null: Draining");
+    CK_LOGD("VideoDecoder::Decode Input buffer null: Draining");
     return Drain(aVideoFrame);
   }
 
   DecodeData* data = new DecodeData();
   Assign(data->mBuffer, aInputBuffer.data, aInputBuffer.data_size);
   data->mTimestamp = aInputBuffer.timestamp;
   data->mCrypto = CryptoMetaData(&aInputBuffer);
 
-  CK_LOGD("VideoDecoder::DecodeTask");
   AutoPtr<DecodeData> d(data);
   HRESULT hr;
 
   if (!data || !mDecoder) {
     CK_LOGE("Decode job not set up correctly!");
     return Status::kDecodeError;
   }
 
@@ -95,97 +99,100 @@ VideoDecoder::Decode(const InputBuffer& 
       return rv;
     }
   }
 
   hr = mDecoder->Input(buffer.data(),
                        buffer.size(),
                        data->mTimestamp);
 
-  CK_LOGD("VideoDecoder::DecodeTask() Input ret hr=0x%x\n", hr);
+  CK_LOGD("VideoDecoder::Decode() Input ret hr=0x%x", hr);
 
 
   if (FAILED(hr)) {
     assert(hr != MF_E_TRANSFORM_NEED_MORE_INPUT);
 
-    CK_LOGE("VideoDecoder::DecodeTask() decode failed ret=0x%x%s\n",
+    CK_LOGE("VideoDecoder::Decode() decode failed ret=0x%x%s",
       hr,
       ((hr == MF_E_NOTACCEPTING) ? " (MF_E_NOTACCEPTING)" : ""));
     CK_LOGD("Decode failed. The decoder is not accepting input");
     return Status::kDecodeError;
   }
 
   return OutputFrame(aVideoFrame);
 }
 
 Status VideoDecoder::OutputFrame(VideoFrame* aVideoFrame) {
+  CK_LOGD("VideoDecoder::OutputFrame");
+
   HRESULT hr = S_OK;
 
   // Read all the output from the decoder. Ideally, this would be a while loop
   // where we read the output and check the result as the condition. However,
   // this produces a memory leak connected to assigning a new CComPtr to the
   // address of the old one, which avoids the CComPtr cleaning up.
   while (true) {
     CComPtr<IMFSample> output;
     hr = mDecoder->Output(&output);
 
     if (hr != S_OK) {
       break;
     }
 
-    CK_LOGD("VideoDecoder::DecodeTask() output ret=0x%x\n", hr);
+    CK_LOGD("VideoDecoder::OutputFrame Decoder output ret=0x%x", hr);
 
     mOutputQueue.push(output);
-    CK_LOGD("Queue size: %u", mOutputQueue.size());
+    CK_LOGD("VideoDecoder::OutputFrame: Queue size: %u", mOutputQueue.size());
   }
 
   // If we don't have any inputs, we need more data.
   if (mOutputQueue.empty()) {
     CK_LOGD("Decode failed. Not enought data; Requesting more input");
     return Status::kNeedMoreData;
   }
 
   // We will get a MF_E_TRANSFORM_NEED_MORE_INPUT every time, as we always
   // consume everything in the buffer.
   if (hr != MF_E_TRANSFORM_NEED_MORE_INPUT && FAILED(hr)) {
-    CK_LOGD("Decode failed output ret=0x%x\n", hr);
+    CK_LOGD("Decode failed output ret=0x%x", hr);
     return Status::kDecodeError;
   }
 
   CComPtr<IMFSample> result = mOutputQueue.front();
   mOutputQueue.pop();
 
   // The Chromium CDM API doesn't have support for negative strides, though
   // they are theoretically possible in real world data.
   if (mDecoder->GetStride() <= 0) {
+    CK_LOGD("VideoDecoder::OutputFrame Failed! (negative stride)");
     return Status::kDecodeError;
   }
 
   hr = SampleToVideoFrame(result,
                           mDecoder->GetFrameWidth(),
                           mDecoder->GetFrameHeight(),
                           mDecoder->GetStride(),
                           aVideoFrame);
   if (FAILED(hr)) {
+    CK_LOGD("VideoDecoder::OutputFrame Failed!");
     return Status::kDecodeError;
   }
 
-  CK_LOGD("Decode succeeded.");
+  CK_LOGD("VideoDecoder::OutputFrame Succeeded.");
   return Status::kSuccess;
 }
 
 HRESULT
 VideoDecoder::SampleToVideoFrame(IMFSample* aSample,
                                  int32_t aWidth,
                                  int32_t aHeight,
                                  int32_t aStride,
                                  VideoFrame* aVideoFrame)
 {
-  CK_LOGD("[%p] VideoDecoder::SampleToVideoFrame()\n", this);
-  assert(aSample);
+  CK_LOGD("[%p] VideoDecoder::SampleToVideoFrame()", this);
 
   ENSURE(aSample != nullptr, E_POINTER);
   ENSURE(aVideoFrame != nullptr, E_POINTER);
 
   HRESULT hr;
   CComPtr<IMFMediaBuffer> mediaBuffer;
 
   aVideoFrame->SetFormat(kI420);
@@ -229,26 +236,28 @@ VideoDecoder::SampleToVideoFrame(IMFSamp
 
   aVideoFrame->SetSize(Size(aWidth, aHeight));
 
   uint64_t bufferSize = ySize + 2 * uSize;
 
   // If the buffer is bigger than the max for a 32 bit, fail to avoid buffer
   // overflows.
   if (bufferSize > UINT32_MAX) {
-    return Status::kDecodeError;
+    CK_LOGD("VideoDecoder::SampleToFrame Buffersize bigger than UINT32_MAX");
+    return E_FAIL;
   }
 
   // Get the buffer from the host.
   Buffer* buffer = mHost->Allocate(bufferSize);
   aVideoFrame->SetFrameBuffer(buffer);
 
   // Make sure the buffer is non-null (allocate guarantees it will be of
   // sufficient size).
   if (!buffer) {
+    CK_LOGD("VideoDecoder::SampleToFrame Out of memory");
     return E_OUTOFMEMORY;
   }
 
   uint8_t* outBuffer = buffer->Data();
 
   aVideoFrame->SetPlaneOffset(VideoFrame::kYPlane, 0);
 
   // Offset is the size of the copied y data.
@@ -304,15 +313,17 @@ VideoDecoder::Drain(VideoFrame* aVideoFr
 
   // Return any pending output.
   return OutputFrame(aVideoFrame);
 }
 
 void
 VideoDecoder::DecodingComplete()
 {
+  CK_LOGD("VideoDecoder::DecodingComplete()");
+
   mHasShutdown = true;
 
   // Release the reference we added in the constructor. There may be
   // WrapRefCounted tasks that also hold references to us, and keep
   // us alive a little longer.
   Release();
 }