Reland r59093008 "Add logging capability to CDM adapter".

Fixed widevine_cdm.gyp.

Original CL description:

The CDM adapter is a pepper plugin and it should not depend on base/. Therefore
we cannot use base/logging.h directly. Instead, add CDM_DLOG, which is a
simplified version of it.

Also add CdmAdapter::ConsoleLog() for JS console logs.

BUG=320065,328486
TEST=Log works on Linux.
R=dalecurtis@chromium.org, ddorwin@chromium.org
TBR=dalecurtis@chromium.org, ddorwin@chromium.org

Review URL: https://codereview.chromium.org/100413006

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@240944 0039d316-1c4b-4281-b951-d872f2087c98

5 files changed, 245 insertions, 4 deletions

diff --git a/media/cdm/ppapi/cdm_adapter.cc b/media/cdm/ppapi/cdm_adapter.cc
index 209335b..d928903 100644
--- a/media/cdm/ppapi/cdm_adapter.cc
+++ b/media/cdm/ppapi/cdm_adapter.cc
@@ -5,7 +5,9 @@
 #include "media/cdm/ppapi/cdm_adapter.h"
 
 #include "media/cdm/ppapi/cdm_helpers.h"
+#include "media/cdm/ppapi/cdm_logging.h"
 #include "media/cdm/ppapi/supported_cdm_versions.h"
+#include "ppapi/c/ppb_console.h"
 
 #if defined(CHECK_DOCUMENT_URL)
 #include "ppapi/cpp/dev/url_util_dev.h"
@@ -14,6 +16,12 @@
 
 namespace {
 
+#if !defined(NDEBUG)
+  #define DLOG_TO_CONSOLE(message) LogToConsole(message);
+#else
+  #define DLOG_TO_CONSOLE(message) (void)(message);
+#endif
+
 bool IsMainThread() {
   return pp::Module::Get()->core()->IsMainThread();
 }
@@ -230,7 +238,14 @@ bool CdmAdapter::CreateCdmInstance(const std::string& key_system) {
   PP_DCHECK(!cdm_);
   cdm_ = make_linked_ptr(CdmWrapper::Create(
       key_system.data(), key_system.size(), GetCdmHost, this));
-  return (cdm_ != NULL);
+  bool success = cdm_ != NULL;
+
+  const std::string message = "CDM instance for " + key_system +
+                              (success ? "" : " could not be") + " created.";
+  DLOG_TO_CONSOLE(message);
+  CDM_DLOG() << message;
+
+  return success;
 }
 
 // No KeyErrors should be reported in this function because they cannot be
@@ -781,6 +796,7 @@ bool CdmAdapter::IsValidVideoFrame(const LinkedVideoFrame& video_frame) {
       !video_frame->FrameBuffer() ||
       (video_frame->Format() != cdm::kI420 &&
        video_frame->Format() != cdm::kYv12)) {
+    CDM_DLOG() << "Invalid video frame!";
     return false;
   }
 
@@ -800,6 +816,15 @@ bool CdmAdapter::IsValidVideoFrame(const LinkedVideoFrame& video_frame) {
   return true;
 }
 
+#if !defined(NDEBUG)
+void CdmAdapter::LogToConsole(const pp::Var& value) {
+  PP_DCHECK(IsMainThread());
+  const PPB_Console* console = reinterpret_cast<const PPB_Console*>(
+      pp::Module::Get()->GetBrowserInterface(PPB_CONSOLE_INTERFACE));
+  console->Log(pp_instance(), PP_LOGLEVEL_LOG, value.pp_var());
+}
+#endif  // !defined(NDEBUG)
+
 void CdmAdapter::SendPlatformChallenge(
     const char* service_id, uint32_t service_id_length,
     const char* challenge, uint32_t challenge_length) {
@@ -836,13 +861,15 @@ void CdmAdapter::SendPlatformChallenge(
 
 void CdmAdapter::EnableOutputProtection(uint32_t desired_protection_mask) {
 #if defined(OS_CHROMEOS)
-  output_protection_.EnableProtection(
+  int32_t result = output_protection_.EnableProtection(
       desired_protection_mask, callback_factory_.NewCallback(
           &CdmAdapter::EnableProtectionDone));
 
   // Errors are ignored since clients must call QueryOutputProtectionStatus() to
   // inspect the protection status on a regular basis.
-  // TODO(dalecurtis): It'd be nice to log a message or non-fatal error here...
+
+  if (result != PP_OK && result != PP_OK_COMPLETIONPENDING)
+    CDM_DLOG() << __FUNCTION__ << " failed!";
 #endif
 }
 
@@ -899,6 +926,7 @@ void CdmAdapter::SendPlatformChallengeDone(int32_t result) {
   challenge_in_progress_ = false;
 
   if (result != PP_OK) {
+    CDM_DLOG() << __FUNCTION__ << ": Platform challenge failed!";
     cdm::PlatformChallengeResponse response = {};
     cdm_->OnPlatformChallengeResponse(response);
     return;
@@ -928,7 +956,7 @@ void CdmAdapter::SendPlatformChallengeDone(int32_t result) {
 void CdmAdapter::EnableProtectionDone(int32_t result) {
   // Does nothing since clients must call QueryOutputProtectionStatus() to
   // inspect the protection status on a regular basis.
-  // TODO(dalecurtis): It'd be nice to log a message or non-fatal error here...
+  CDM_DLOG() << __FUNCTION__ << " : " << result;
 }
 
 void CdmAdapter::QueryOutputProtectionStatusDone(int32_t result) {
@@ -969,6 +997,7 @@ void* GetCdmHost(int host_interface_version, void* user_data) {
   PP_DCHECK(IsSupportedCdmHostVersion(host_interface_version));
 
   CdmAdapter* cdm_adapter = static_cast<CdmAdapter*>(user_data);
+  CDM_DLOG() << "Create CDM Host with version " << host_interface_version;
   switch (host_interface_version) {
     case cdm::Host_3::kVersion:
       return static_cast<cdm::Host_3*>(cdm_adapter);
diff --git a/media/cdm/ppapi/cdm_adapter.h b/media/cdm/ppapi/cdm_adapter.h
index ec7145d..d256913 100644
--- a/media/cdm/ppapi/cdm_adapter.h
+++ b/media/cdm/ppapi/cdm_adapter.h
@@ -170,6 +170,13 @@ class CdmAdapter : public pp::Instance,
 
   bool IsValidVideoFrame(const LinkedVideoFrame& video_frame);
 
+#if !defined(NDEBUG)
+  // Logs the given message to the JavaScript console associated with the
+  // CDM adapter instance. The name of the CDM adapter issuing the log message
+  // will be automatically prepended to the message.
+  void LogToConsole(const pp::Var& value);
+#endif  // !defined(NDEBUG)
+
 #if defined(OS_CHROMEOS)
   void SendPlatformChallengeDone(int32_t result);
   void EnableProtectionDone(int32_t result);
diff --git a/media/cdm/ppapi/cdm_logging.cc b/media/cdm/ppapi/cdm_logging.cc
new file mode 100644
index 0000000..ff05930
--- /dev/null
+++ b/media/cdm/ppapi/cdm_logging.cc
@@ -0,0 +1,137 @@
+// Copyright 2013 The Chromium Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+// Only compile this file in debug build. This gives us one more level of
+// protection that if the linker tries to link in strings/symbols appended to
+// "DLOG() <<" in release build (which it shouldn't), we'll get "undefined
+// reference" errors.
+#if !defined(NDEBUG)
+
+#include "media/cdm/ppapi/cdm_logging.h"
+
+#include "base/basictypes.h"
+
+#if defined(OS_WIN)
+#include <io.h>
+#include <windows.h>
+#elif defined(OS_MACOSX)
+#include <mach/mach.h>
+#include <mach/mach_time.h>
+#include <mach-o/dyld.h>
+#elif defined(OS_POSIX)
+#include <sys/syscall.h>
+#include <time.h>
+#endif
+
+#if defined(OS_POSIX)
+#include <errno.h>
+#include <pthread.h>
+#include <stdlib.h>
+#include <stdio.h>
+#include <string.h>
+#include <unistd.h>
+#endif
+
+#include <iomanip>
+#include <string>
+
+namespace media {
+
+namespace {
+
+// Helper functions to wrap platform differences.
+
+int32 CurrentProcessId() {
+#if defined(OS_WIN)
+  return GetCurrentProcessId();
+#elif defined(OS_POSIX)
+  return getpid();
+#endif
+}
+
+int32 CurrentThreadId() {
+  // Pthreads doesn't have the concept of a thread ID, so we have to reach down
+  // into the kernel.
+#if defined(OS_LINUX)
+  return syscall(__NR_gettid);
+#elif defined(OS_ANDROID)
+  return gettid();
+#elif defined(OS_SOLARIS)
+  return pthread_self();
+#elif defined(OS_POSIX)
+  return reinterpret_cast<int64>(pthread_self());
+#elif defined(OS_WIN)
+  return static_cast<int32>(::GetCurrentThreadId());
+#endif
+}
+
+uint64 TickCount() {
+#if defined(OS_WIN)
+  return GetTickCount();
+#elif defined(OS_MACOSX)
+  return mach_absolute_time();
+#elif defined(OS_POSIX)
+  struct timespec ts;
+  clock_gettime(CLOCK_MONOTONIC, &ts);
+
+  uint64 absolute_micro =
+    static_cast<int64>(ts.tv_sec) * 1000000 +
+    static_cast<int64>(ts.tv_nsec) / 1000;
+
+  return absolute_micro;
+#endif
+}
+
+}  // namespace
+
+CdmLogMessage::CdmLogMessage(const char* file, int line) {
+  std::string filename(file);
+  size_t last_slash_pos = filename.find_last_of("\\/");
+  if (last_slash_pos != std::string::npos)
+    filename = filename.substr(last_slash_pos + 1);
+
+  stream_ << '[';
+
+  // Process and thread ID.
+  stream_ << CurrentProcessId() << ':';
+  stream_ << CurrentThreadId() << ':';
+
+  // Time and tick count.
+  time_t t = time(NULL);
+  struct tm local_time = {0};
+#if _MSC_VER >= 1400
+  localtime_s(&local_time, &t);
+#else
+  localtime_r(&t, &local_time);
+#endif
+  struct tm* tm_time = &local_time;
+  stream_ << std::setfill('0')
+          << std::setw(2) << 1 + tm_time->tm_mon
+          << std::setw(2) << tm_time->tm_mday
+          << '/'
+          << std::setw(2) << tm_time->tm_hour
+          << std::setw(2) << tm_time->tm_min
+          << std::setw(2) << tm_time->tm_sec
+          << ':';
+  stream_ << TickCount() << ':';
+
+  // File name.
+  stream_ << filename << "(" << line << ")] ";
+}
+
+CdmLogMessage::~CdmLogMessage() {
+  // Use std::cout explicitly for the line break. This limits the use of this
+  // class only to the definition of DLOG() (which also uses std::cout).
+  //
+  // This appends "std::endl" after all other messages appended to DLOG(),
+  // which relies on the C++ standard ISO/IEC 14882:1998(E) $12.2.3:
+  // "Temporary objects are destroyed as the last step in evaluating the
+  // full-expression (1.9) that (lexically) contains the point where they were
+  // created."
+  std::cout << std::endl;
+}
+
+}  // namespace media
+
+#endif  // !defined(NDEBUG)
diff --git a/media/cdm/ppapi/cdm_logging.h b/media/cdm/ppapi/cdm_logging.h
new file mode 100644
index 0000000..a705918
--- /dev/null
+++ b/media/cdm/ppapi/cdm_logging.h
@@ -0,0 +1,66 @@
+// Copyright 2013 The Chromium Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+// This file defines useful logging macros/methods for CDM adapter.
+
+#ifndef MEDIA_CDM_PPAPI_CDM_LOGGING_H_
+#define MEDIA_CDM_PPAPI_CDM_LOGGING_H_
+
+#include <iostream>
+#include <sstream>
+#include <string>
+
+namespace media {
+
+namespace {
+
+// The following classes/macros are adapted from base/logging.h.
+
+// This class is used to explicitly ignore values in the conditional
+// logging macros.  This avoids compiler warnings like "value computed
+// is not used" and "statement has no effect".
+class LogMessageVoidify {
+ public:
+  LogMessageVoidify() {}
+  // This has to be an operator with a precedence lower than << but
+  // higher than ?:
+  void operator&(std::ostream&) {}
+};
+
+}  // namespace
+
+// This class serves two purposes:
+// (1) It adds common headers to the log message, e.g. timestamp, process ID.
+// (2) It adds a line break at the end of the log message.
+// This class is copied and modified from base/logging.* but is quite different
+// in terms of how things work. This class is designed to work only with the
+// CDM_DLOG() defined below and should not be used for other purposes.
+class CdmLogMessage {
+ public:
+  CdmLogMessage(const char* file, int line);
+  ~CdmLogMessage();
+
+  std::string message() { return stream_.str(); }
+
+ private:
+  std::ostringstream stream_;
+};
+
+// Helper macro which avoids evaluating the arguments to a stream if
+// the condition doesn't hold.
+#define CDM_LAZY_STREAM(stream, condition) \
+  !(condition) ? (void) 0 : LogMessageVoidify() & (stream)
+
+#define CDM_DLOG() CDM_LAZY_STREAM(std::cout, CDM_DLOG_IS_ON()) \
+  << CdmLogMessage(__FILE__, __LINE__).message()
+
+#if defined(NDEBUG)
+#define CDM_DLOG_IS_ON() false
+#else
+#define CDM_DLOG_IS_ON() true
+#endif
+
+}  // namespace media
+
+#endif  // MEDIA_CDM_PPAPI_CDM_LOGGING_H_
diff --git a/media/media_cdm.gypi b/media/media_cdm.gypi
index 8ebcfbe89..d495e34 100644
--- a/media/media_cdm.gypi
+++ b/media/media_cdm.gypi
@@ -103,6 +103,8 @@
         'cdm/ppapi/cdm_adapter.h',
         'cdm/ppapi/cdm_helpers.cc',
         'cdm/ppapi/cdm_helpers.h',
+        'cdm/ppapi/cdm_logging.cc',
+        'cdm/ppapi/cdm_logging.h',
         'cdm/ppapi/cdm_wrapper.h',
         'cdm/ppapi/linked_ptr.h',
         'cdm/ppapi/supported_cdm_versions.h',