Change Chromoting logger to be setup in plugin's NP_Initialize.

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/message_loop_proxy.h"
 #include "base/sys_string_conversions.h"
 #include "base/threading/platform_thread.h"
 #include "base/utf_string_conversions.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_log_handler.h"
 #include "remoting/host/plugin/policy_hack/nat_policy.h"
 #include "remoting/host/register_support_host_request.h"
 #include "remoting/host/support_access_verifier.h"
 #include "remoting/host/ui_strings.h"
 
 namespace remoting {
 
 // Supported Javascript interface:
 // readonly attribute string accessCode;
 // readonly attribute int accessCodeLifetime;
@@ skipping 35 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,
     PluginMessageLoopProxy::Delegate* plugin_thread_delegate)
     : plugin_(plugin),
       parent_(parent),
       state_(kDisconnected),
       np_thread_id_(base::PlatformThread::CurrentId()),
       plugin_message_loop_proxy_(
           new PluginMessageLoopProxy(plugin_thread_delegate)),
       host_context_(plugin_message_loop_proxy_),
       failed_login_attempts_(0),
       disconnected_event_(true, false),
       nat_traversal_enabled_(false),
       policy_received_(false) {
-  // 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;
 }
 
 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;
-  g_logging_scriptable_object = NULL;
+  HostLogHandler::UnregisterLoggingScriptObject(this);
 
   plugin_message_loop_proxy_->Detach();
 
   // Stop listening for policy updates.
   if (nat_policy_.get()) {
     base::WaitableEvent nat_policy_stopped_(true, false);
     nat_policy_->StopWatching(&nat_policy_stopped_);
     nat_policy_stopped_.Wait();
     nat_policy_.reset();
   }
@@ skipping 149 matching lines @@
     } else {
       SetException("SetProperty: unexpected type for property " +
                    property_name);
     }
     return false;
   }
 
   if (property_name == kAttrNameLogDebugInfo) {
     if (NPVARIANT_IS_OBJECT(*value)) {
       log_debug_info_func_ = NPVARIANT_TO_OBJECT(*value);
+      HostLogHandler::RegisterLoggingScriptObject(this);
       return true;
     } else {
       SetException("SetProperty: unexpected type for property " +
                    property_name);
     }
     return false;
   }
 
   return false;
 }
@@ skipping 294 matching lines @@
     return;
   }
   state_ = state;
   if (on_state_changed_func_.get()) {
     VLOG(2) << "Calling state changed " << state;
     bool is_good = InvokeAndIgnoreResult(on_state_changed_func_.get(), 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) {
-  // The |g_logging_to_plugin| check is to prevent logging to the scriptable
-  // object if we're already in the middle of logging.
-  // This can occur if we try to log an error while we're in the scriptable
-  // object logging code.
-  if (g_logging_scriptable_object && !g_logging_to_plugin) {
-    g_logging_to_plugin = true;
-    std::string message = remoting::GetTimestampString();
-    message += (str.c_str() + message_start);
-    g_logging_scriptable_object->LogDebugInfo(message);
-    g_logging_to_plugin = false;
-  }
-  if (g_logging_old_handler)
-    return (g_logging_old_handler)(severity, file, line, message_start, str);
-  return false;
+void HostNPScriptObject::PostLogDebugInfo(const std::string& message) {
+  // Always post (even if we're already on the correct thread) so that debug
+  // log messages aren't shown out of order.
+  plugin_message_loop_proxy_->PostTask(
+      FROM_HERE, base::Bind(&HostNPScriptObject::LogDebugInfo,
+                            base::Unretained(this), message));
 }
 
 void HostNPScriptObject::LogDebugInfo(const std::string& message) {
-  if (!plugin_message_loop_proxy_->BelongsToCurrentThread()) {
-    plugin_message_loop_proxy_->PostTask(
-        FROM_HERE, base::Bind(&HostNPScriptObject::LogDebugInfo,
-                              base::Unretained(this), message));
-    return;
-  }
-
   if (log_debug_info_func_.get()) {
     NPVariant log_message;
     STRINGZ_TO_NPVARIANT(message.c_str(), log_message);
     bool is_good = InvokeAndIgnoreResult(log_debug_info_func_.get(),
                                          &log_message, 1);
-    LOG_IF(ERROR, !is_good) << "LogDebugInfo failed";
+    if (!is_good) {
+      // Note that we can't use LOG here because we're currently in the middle
+      // of handling a LOG message.
+      printf("ERROR - LogDebugInfo failed\n");

[Wez, 2011/08/30 05:20:02]

If we place a check around the invokation to protect against re-entrancy, like
we have in the client, then we can use LOG here.

[garykac, 2011/08/31 00:59:00]

Our log message handler is asynchronous, so any flag will cover the posting
(PostLogDebugInfo), but not the actual handling (LogDebugInfo).

I couldn't think of a clean way of doing this and it didn't seem to be worth the
time to fix it for this single message.

+    }
   }
 }
 
 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());
   LOG(INFO) << exception_string;
 }
 
 void HostNPScriptObject::LocalizeStrings() {
@@ skipping 51 matching lines @@
                                                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);
   return is_good;
 }
 
 }  // namespace remoting