Modify Chromoting logging to hook into base logging.

remoting/host/plugin/host_script_object.cc

 // Copyright (c) 2011 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.
 
 #include "remoting/host/plugin/host_script_object.h"
 
 #include "base/bind.h"
 #include "base/message_loop.h"
 #include "base/threading/platform_thread.h"
 #include "remoting/base/auth_token_util.h"
+#include "remoting/base/util.h"
 #include "remoting/host/chromoting_host.h"
 #include "remoting/host/chromoting_host_context.h"
 #include "remoting/host/desktop_environment.h"
 #include "remoting/host/host_config.h"
 #include "remoting/host/host_key_pair.h"
 #include "remoting/host/in_memory_host_config.h"
 #include "remoting/host/plugin/host_plugin_utils.h"
 #include "remoting/host/register_support_host_request.h"
 #include "remoting/host/support_access_verifier.h"
 
@@ skipping 36 matching lines @@
 const char* kAttrNameRequestedAccessCode = "REQUESTED_ACCESS_CODE";
 const char* kAttrNameReceivedAccessCode = "RECEIVED_ACCESS_CODE";
 const char* kAttrNameConnected = "CONNECTED";
 const char* kAttrNameAffirmingConnection = "AFFIRMING_CONNECTION";
 const char* kAttrNameError = "ERROR";
 
 const int kMaxLoginAttempts = 5;
 
 }  // namespace
 
+// This flag blocks LOGs to the UI if we're already in the middle of logging
+// to the UI. This prevents a potential infinite loop if we encounter an error
+// while sending the log message to the UI.
+static bool g_logging_to_plugin = false;
+static HostNPScriptObject* g_logging_scriptable_object = NULL;
+static logging::LogMessageHandlerFunction g_logging_old_handler = NULL;
+
 HostNPScriptObject::HostNPScriptObject(NPP plugin, NPObject* parent)
     : plugin_(plugin),
       parent_(parent),
       state_(kDisconnected),
       log_debug_info_func_(NULL),
       on_state_changed_func_(NULL),
       np_thread_id_(base::PlatformThread::CurrentId()),
       failed_login_attempts_(0),
       disconnected_event_(true, false) {
-  logger_.reset(new HostPluginLogger(this));
-  logger_->VLog(2, "HostNPScriptObject");
+  // Set up log message handler.
+  // Note that this approach doesn't quite support having multiple instances
+  // of Chromoting running. In that case, the most recently opened tab will
+  // grab all the debug log messages, and when any Chromoting tab is closed
+  // the logging handler will go away.
+  // Since having multiple Chromoting tabs is not a primary use case, and this
+  // is just debug logging, we're punting improving debug log support for that
+  // case.
+  if (g_logging_old_handler == NULL)
+    g_logging_old_handler = logging::GetLogMessageHandler();
+  logging::SetLogMessageHandler(&LogToUI);
+  g_logging_scriptable_object = this;
+
+  VLOG(2) << "HostNPScriptObject";
   host_context_.SetUITaskPostFunction(base::Bind(
       &HostNPScriptObject::PostTaskToNPThread, base::Unretained(this)));
 }
 
 HostNPScriptObject::~HostNPScriptObject() {
   CHECK_EQ(base::PlatformThread::CurrentId(), np_thread_id_);
 
   // Shutdown DesktopEnvironment first so that it doesn't try to post
   // tasks on the UI thread while we are stopping the host.
   desktop_environment_->Shutdown();
 
+  logging::SetLogMessageHandler(g_logging_old_handler_);
+  g_logging_old_handler_ = NULL;

[Wez, 2011/08/02 23:45:26]

This code isn't symmetric with the constructor; if multiple instances are
created and destroyed then we'll tear down our logging handler as soon as the
first is destroyed, and only reinstate it if a new instance is started.

Given that hooking logging has global effect, it might make more sense to hook
in NPP_Initialize, and un-hook in NPP_Shutdown?

+  g_logging_scriptable_object_ = NULL;
+
   // Disconnect synchronously. We cannot disconnect asynchronously
   // here because |host_context_| needs to be stopped on the plugin
   // thread, but the plugin thread may not exist after the instance
   // is destroyed.
   destructing_.Set();
   disconnected_event_.Reset();
   DisconnectInternal();
   disconnected_event_.Wait();
 
   // Stop all threads.
   host_context_.Stop();
 
   if (log_debug_info_func_) {
     g_npnetscape_funcs->releaseobject(log_debug_info_func_);
   }
   if (on_state_changed_func_) {
     g_npnetscape_funcs->releaseobject(on_state_changed_func_);
   }
 }
 
 bool HostNPScriptObject::Init() {
-  logger_->VLog(2, "Init");
+  VLOG(2) << "Init";
   // TODO(wez): This starts a bunch of threads, which might fail.
   host_context_.Start();
   return true;
 }
 
 bool HostNPScriptObject::HasMethod(const std::string& method_name) {
-  logger_->VLog(2, "HasMethod %s", method_name.c_str());
+  VLOG(2) << "HasMethod " << method_name;
   CHECK_EQ(base::PlatformThread::CurrentId(), np_thread_id_);
   return (method_name == kFuncNameConnect ||
           method_name == kFuncNameDisconnect);
 }
 
 bool HostNPScriptObject::InvokeDefault(const NPVariant* args,
                                        uint32_t argCount,
                                        NPVariant* result) {
-  logger_->VLog(2, "InvokeDefault");
+  VLOG(2) << "InvokeDefault";
   CHECK_EQ(base::PlatformThread::CurrentId(), np_thread_id_);
   SetException("exception during default invocation");
   return false;
 }
 
 bool HostNPScriptObject::Invoke(const std::string& method_name,
                                 const NPVariant* args,
                                 uint32_t argCount,
                                 NPVariant* result) {
-  logger_->VLog(2, "Invoke %s", method_name.c_str());
+  VLOG(2) << "Invoke " << method_name;
   CHECK_EQ(base::PlatformThread::CurrentId(), np_thread_id_);
   if (method_name == kFuncNameConnect) {
     return Connect(args, argCount, result);
   } else if (method_name == kFuncNameDisconnect) {
     return Disconnect(args, argCount, result);
   } else {
     SetException("Invoke: unknown method " + method_name);
     return false;
   }
 }
 
 bool HostNPScriptObject::HasProperty(const std::string& property_name) {
-  logger_->VLog(2, "HasProperty %s", property_name.c_str());
+  VLOG(2) << "HasProperty " << property_name;
   CHECK_EQ(base::PlatformThread::CurrentId(), np_thread_id_);
   return (property_name == kAttrNameAccessCode ||
           property_name == kAttrNameAccessCodeLifetime ||
           property_name == kAttrNameState ||
           property_name == kAttrNameLogDebugInfo ||
           property_name == kAttrNameOnStateChanged ||
           property_name == kAttrNameDisconnected ||
           property_name == kAttrNameRequestedAccessCode ||
           property_name == kAttrNameReceivedAccessCode ||
           property_name == kAttrNameConnected ||
           property_name == kAttrNameAffirmingConnection ||
           property_name == kAttrNameError);
 }
 
 bool HostNPScriptObject::GetProperty(const std::string& property_name,
                                      NPVariant* result) {
-  logger_->VLog(2, "GetProperty %s", property_name.c_str());
+  VLOG(2) << "GetProperty " << property_name;
   CHECK_EQ(base::PlatformThread::CurrentId(), np_thread_id_);
   if (!result) {
     SetException("GetProperty: NULL result");
     return false;
   }
 
   if (property_name == kAttrNameOnStateChanged) {
     OBJECT_TO_NPVARIANT(on_state_changed_func_, *result);
     return true;
   } else if (property_name == kAttrNameLogDebugInfo) {
@@ skipping 27 matching lines @@
     INT32_TO_NPVARIANT(kError, *result);
     return true;
   } else {
     SetException("GetProperty: unsupported property " + property_name);
     return false;
   }
 }
 
 bool HostNPScriptObject::SetProperty(const std::string& property_name,
                                      const NPVariant* value) {
-  logger_->VLog(2, "SetProperty %s", property_name.c_str());
+  VLOG(2) <<  "SetProperty " << property_name;
   CHECK_EQ(base::PlatformThread::CurrentId(), np_thread_id_);
 
   if (property_name == kAttrNameOnStateChanged) {
     if (NPVARIANT_IS_OBJECT(*value)) {
       if (on_state_changed_func_) {
         g_npnetscape_funcs->releaseobject(on_state_changed_func_);
       }
       on_state_changed_func_ = NPVARIANT_TO_OBJECT(*value);
       if (on_state_changed_func_) {
         g_npnetscape_funcs->retainobject(on_state_changed_func_);
@@ skipping 20 matching lines @@
       SetException("SetProperty: unexpected type for property " +
                    property_name);
     }
     return false;
   }
 
   return false;
 }
 
 bool HostNPScriptObject::RemoveProperty(const std::string& property_name) {
-  logger_->VLog(2, "RemoveProperty %s", property_name.c_str());
+  VLOG(2) << "RemoveProperty " << property_name;
   CHECK_EQ(base::PlatformThread::CurrentId(), np_thread_id_);
   return false;
 }
 
 bool HostNPScriptObject::Enumerate(std::vector<std::string>* values) {
-  logger_->VLog(2, "Enumerate");
+  VLOG(2) << "Enumerate";
   CHECK_EQ(base::PlatformThread::CurrentId(), np_thread_id_);
   const char* entries[] = {
     kAttrNameAccessCode,
     kAttrNameState,
     kAttrNameLogDebugInfo,
     kAttrNameOnStateChanged,
     kFuncNameConnect,
     kFuncNameDisconnect,
     kAttrNameDisconnected,
     kAttrNameRequestedAccessCode,
@@ skipping 33 matching lines @@
 
   OnStateChanged(kDisconnected);
 }
 
 // string uid, string auth_token
 bool HostNPScriptObject::Connect(const NPVariant* args,
                                  uint32_t arg_count,
                                  NPVariant* result) {
   CHECK_EQ(base::PlatformThread::CurrentId(), np_thread_id_);
 
-  LogDebugInfo("Connecting...");
+  LOG(INFO) << "Connecting...";
 
   if (arg_count != 2) {
     SetException("connect: bad number of arguments");
     return false;
   }
 
   std::string uid = StringFromNPVariant(args[0]);
   if (uid.empty()) {
     SetException("connect: bad uid argument");
     return false;
@@ skipping 149 matching lines @@
     return;
 
   if (!host_context_.IsUIThread()) {
     host_context_.PostTaskToUIThread(
         FROM_HERE, base::Bind(&HostNPScriptObject::OnStateChanged,
                               base::Unretained(this), state));
     return;
   }
   state_ = state;
   if (on_state_changed_func_) {
-    logger_->VLog(2, "Calling state changed %s", state);
+    VLOG(2) << "Calling state changed " << state;
     bool is_good = InvokeAndIgnoreResult(on_state_changed_func_, NULL, 0);
     LOG_IF(ERROR, !is_good) << "OnStateChanged failed";
   }
 }
 
+// static
+bool HostNPScriptObject::LogToUI(int severity, const char* file, int line,
+                                 size_t message_start,
+                                 const std::string& str) {
+  if (g_logging_scriptable_object) {
+    std::string message = remoting::GetTimestampString();
+    message += (str.c_str() + message_start);
+    g_logging_scriptable_object->LogDebugInfo(message);
+  }
+  if (g_logging_old_handler)
+    return (g_logging_old_handler)(severity, file, line, message_start, str);
+  return false;
+}
+
 void HostNPScriptObject::LogDebugInfo(const std::string& message) {
   if (destructing_.IsSet())
     return;
 
   if (!host_context_.IsUIThread()) {
     host_context_.PostTaskToUIThread(
         FROM_HERE, base::Bind(&HostNPScriptObject::LogDebugInfo,
                               base::Unretained(this), message));
     return;
   }
-  if (log_debug_info_func_) {
+  if (log_debug_info_func_ && !g_logging_to_plugin) {

[Sergey Ulanov, 2011/08/02 18:15:52]

Not sure why we need |g_logging_to_plugin| here. Can you please add comments?
Does it need to be global?

[garykac, 2011/08/02 23:09:51]

Added comments and moved it into the static LogToUI. It's global because we have
only 1 global LogMessage callback eve if there are multiple chromoting
instances.

Notes it stands, the code doesn't 100% properly handle multiple plugins (see
comment near top of file). But spending time on that case is not a priority.

     NPVariant* arg = new NPVariant();
     STRINGZ_TO_NPVARIANT(message.c_str(), *arg);
+    g_logging_to_plugin = true;
     bool is_good = InvokeAndIgnoreResult(log_debug_info_func_, arg, 1);
+    g_logging_to_plugin = false;
     LOG_IF(ERROR, !is_good) << "LogDebugInfo failed";
   }
 }
 
 void HostNPScriptObject::SetException(const std::string& exception_string) {
   CHECK_EQ(base::PlatformThread::CurrentId(), np_thread_id_);
   g_npnetscape_funcs->setexception(parent_, exception_string.c_str());
-  LogDebugInfo(exception_string);
+  LOG(INFO) << exception_string;
 }
 
 bool HostNPScriptObject::InvokeAndIgnoreResult(NPObject* func,
                                                const NPVariant* args,
                                                uint32_t argCount) {
   NPVariant np_result;
   bool is_good = g_npnetscape_funcs->invokeDefault(plugin_, func, args,
                                                    argCount, &np_result);
   if (is_good)
       g_npnetscape_funcs->releasevariantvalue(&np_result);
@@ skipping 15 matching lines @@
 }
 
 // static
 void HostNPScriptObject::NPTaskSpringboard(void* task) {
   base::Closure* real_task = reinterpret_cast<base::Closure*>(task);
   real_task->Run();
   delete real_task;
 }
 
 }  // namespace remoting