Bug 1318965 - Improves the logging in Clearkey r=cpearce
authorJay Harris <jharris@mozilla.com>
Wed, 18 Jan 2017 14:49:58 +1300
changeset 374933 ffbbd9fe609b6e386e7e5600308171f1d92f0078
parent 374932 cc2329247ee15c6adbbbb55d99bdc677ec6b7c67
child 374934 f4b6c78a36f8b9360fd47dacc6d95c24ce60fbd4
push id6996
push userjlorenzo@mozilla.com
push dateMon, 06 Mar 2017 20:48:21 +0000
treeherdermozilla-beta@d89512dab048 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewerscpearce
bugs1318965
milestone53.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 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();
 }