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/task.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/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"
 
 namespace remoting {
@@ skipping 33 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 logging_to_plugin_ = false;

[dmac, 2011/07/21 23:37:07]

again, should these be prefixed with a g? and they shouldn't have a _

[garykac, 2011/08/02 00:15:37]

Done.

+static HostNPScriptObject* logging_scriptable_object_ = NULL;
+static logging::LogMessageHandlerFunction 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");
+  logging_old_handler_ = logging::GetLogMessageHandler();

[dmac, 2011/07/21 23:37:07]

Is this not assuming that HostNPScriptObject is only going to be created once?

[garykac, 2011/08/02 00:15:37]

No, er.. yes. It's not not assuming...  I mean it *is* assuming.

Anyway, I fixed it up a bit and added a comment.  It doesn't seem worth the dev
effort to make the debug logging work perfectly for multiple Chromoting tabs.

+  logging::SetLogMessageHandler(&LogToUI);
+  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_);
 
+  logging::SetLogMessageHandler(logging_old_handler_);
+  logging_old_handler_ = NULL;
+  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();
 
   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 == 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 24 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 49 matching lines @@
           base::Bind(&HostNPScriptObject::OnReceivedSupportID,
                      base::Unretained(this),
                      access_verifier.get()))) {
     OnStateChanged(kDisconnected);
     return;
   }
 
   // Create the Host.
   scoped_refptr<ChromotingHost> host =
       ChromotingHost::Create(&host_context_, host_config,
-                             access_verifier.release(), logger_.get());
+                             access_verifier.release());
   host->AddStatusObserver(this);
   host->AddStatusObserver(register_request.get());
   host->set_it2me(true);
 
   // Nothing went wrong, so lets save the host, config and request.
   host_ = host;
   host_config_ = host_config;
   register_request_.reset(register_request.release());
 
   // Start the Host.
@@ skipping 72 matching lines @@
   }
 
   if (!host_context_.IsUIThread()) {
     host_context_.PostToUIThread(
         FROM_HERE,
         NewRunnableMethod(this, &HostNPScriptObject::OnStateChanged, 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 (logging_scriptable_object_ && !logging_to_plugin_) {

[dmac, 2011/07/21 23:37:07]

accessing logging_to_plugin_ from multiple thread problems?

[garykac, 2011/08/02 00:15:37]

Pushed this check down into the UIThread code below (in LogDebugInfo).

+    logging_to_plugin_ = true;
+    std::string message = remoting::GetTimestampString();
+    message += (str.c_str() + message_start);
+    logging_scriptable_object_->LogDebugInfo(message);
+    logging_to_plugin_ = false;
+  }
+  if (logging_old_handler_)
+    return (logging_old_handler_)(severity, file, line, message_start, str);
+  return false;
+}
+
 void HostNPScriptObject::LogDebugInfo(const std::string& message) {
   if (!host_context_.IsUIThread()) {
     host_context_.PostToUIThread(
         FROM_HERE,
         NewRunnableMethod(this, &HostNPScriptObject::LogDebugInfo, message));
     return;
   }
   if (log_debug_info_func_) {
     NPVariant* arg = new NPVariant();
     STRINGZ_TO_NPVARIANT(message.c_str(), *arg);
     bool is_good = InvokeAndIgnoreResult(log_debug_info_func_, arg, 1);
     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 12 matching lines @@
                                             task);
 }
 
 void HostNPScriptObject::NPTaskSpringboard(void* task) {
   Task* real_task = reinterpret_cast<Task*>(task);
   real_task->Run();
   delete real_task;
 }
 
 }  // namespace remoting