Change Chromoting logger to be setup in CreatePlugin.

This fixes a crash that occurred when multiple hosts were shared in the same
browser.

BUG=92078
TEST=manual

Review URL: http://codereview.chromium.org/7648042

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

remoting/host/plugin/host_log_handler.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_log_handler.h"
+
+#include "remoting/base/util.h"
+#include "remoting/host/plugin/host_script_object.h"
+
+namespace remoting {
+
+// Records whether or not we have a scriptable object registered for logging.
+// This is set inside the lock, but is read (in LogToUI) outside of a lock so
+// that we don't needlessly slow down the system when we log.
+static bool g_has_logging_scriptable_object = false;
+
+// The lock that protects the logging globals.
+static base::Lock g_logging_lock;
+
+// The scriptable object that will display the log information to the user.
+static HostNPScriptObject* g_logging_scriptable_object = NULL;
+
+// The previously registered LogMessageHandler. If not NULL, we call this after
+// we're doing processing the log message.
+static logging::LogMessageHandlerFunction g_logging_old_handler = NULL;
+
+// Set to true when we register our global log handler so that we don't try
+// to register it twice.
+static bool g_has_registered_log_handler = false;
+
+// static
+void HostLogHandler::RegisterLogMessageHandler() {
+  base::AutoLock lock(g_logging_lock);
+
+  if (!g_has_registered_log_handler)
+    return;
+
+  LOG(INFO) << "Registering global log handler";
+
+  // Record previous handler so we can call it in a chain.
+  g_logging_old_handler = logging::GetLogMessageHandler();
+
+  // Set up log message handler.
+  // This is not thread-safe so we need it within our lock.
+  // Note that this will not log anything until a scriptable object instance
+  // has been created to handle the log message display.
+  logging::SetLogMessageHandler(&LogToUI);
+}
+
+// static
+void HostLogHandler::RegisterLoggingScriptObject(
+    HostNPScriptObject* script_object) {
+  base::AutoLock lock(g_logging_lock);
+
+  LOG(INFO) << "Registering log handler scriptable object";
+
+  // Register this script object as the one that will handle all logging calls
+  // and display them to the user.
+  // If multiple plugins are run, then the last one registered will handle all
+  // logging for all instances.
+  g_logging_scriptable_object = script_object;
+  g_has_logging_scriptable_object = true;
+}
+
+// static
+void HostLogHandler::UnregisterLoggingScriptObject(
+    HostNPScriptObject* script_object) {
+  base::AutoLock lock(g_logging_lock);
+
+  // Ignore unless we're the currently registered script object.
+  if (script_object != g_logging_scriptable_object)
+    return;
+
+  // Unregister this script object for logging.
+  g_has_logging_scriptable_object = false;
+  g_logging_scriptable_object = NULL;
+
+  LOG(INFO) << "Unregistering log handler scriptable object";
+}
+
+// static
+bool HostLogHandler::LogToUI(int severity, const char* file, int line,
+                             size_t message_start,
+                             const std::string& str) {
+  // Note: We're reading |g_has_logging_scriptable_object| outside of a lock.
+  // This lockless read is done so that we don't needlessly slow down global
+  // logging with a lock for each log message.
+  //
+  // This lockless read is safe because:
+  //
+  // Misreading a false value (when it should be true) means that we'll simply
+  // skip processing a few log messages.
+  //
+  // Misreading a true value (when it should be false) means that we'll take
+  // the lock and check |g_logging_scriptable_object| unnecessarily. This is not
+  // problematic because we always set |g_logging_scriptable_object| inside a
+  // lock.
+  //
+  // Misreading an old cached value is also not problematic for the same
+  // reasons: a mis-read either skips a log message or causes us to take a lock
+  // unnecessarily.
+  if (g_has_logging_scriptable_object) {
+    base::AutoLock lock(g_logging_lock);
+
+    if (g_logging_scriptable_object) {
+      std::string message = remoting::GetTimestampString();
+      message += (str.c_str() + message_start);
+      g_logging_scriptable_object->PostLogDebugInfo(message);
+    }
+  }
+
+  // Call the next log handler in the chain.
+  if (g_logging_old_handler)
+    return (g_logging_old_handler)(severity, file, line, message_start, str);
+
+  return false;
+}
+
+}  // namespace remoting

remoting/host/plugin/host_log_handler.h

+// 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.
+
+#ifndef REMOTING_HOST_PLUGIN_HOST_LOG_HANDLER_H_
+#define REMOTING_HOST_PLUGIN_HOST_LOG_HANDLER_H_
+
+#include <string>
+
+namespace remoting {
+
+class HostNPScriptObject;
+
+class HostLogHandler {
+ public:
+  // Register the log handler.
+  // These should be called from the plugin init/destroy methods so that they
+  // are only called once per plugin process (not once per plugin instance).
+  static void RegisterLogMessageHandler();
+
+  // We don't have the corresponding UnregisterLogMessageHandler because it
+  // is not safe to call it when there are multiple threads that might be
+  // logging.
+
+  static void RegisterLoggingScriptObject(HostNPScriptObject* script_object);
+  static void UnregisterLoggingScriptObject(HostNPScriptObject* script_object);
+
+ private:
+  // A Log Message Handler that is called after each LOG message has been
+  // processed. This must be of type LogMessageHandlerFunction defined in
+  // base/logging.h.
+  static bool LogToUI(int severity, const char* file, int line,
+                      size_t message_start, const std::string& str);
+};
+
+}  // namespace remoting
+
+#endif  // REMOTING_HOST_PLUGIN_HOST_LOG_HANDLER_H_

remoting/host/plugin/host_plugin.cc

@@ -13,6 +13,7 @@
 #include "base/logging.h"
 #include "base/stringize_macros.h"
 #include "remoting/base/plugin_message_loop_proxy.h"
+#include "remoting/host/plugin/host_log_handler.h"
 #include "remoting/host/plugin/host_plugin_utils.h"
 #include "remoting/host/plugin/host_script_object.h"
 #include "third_party/npapi/bindings/npapi.h"
@@ -43,6 +44,7 @@ uint64_t __cdecl __udivdi3(uint64_t a, uint64_t b) {
 #endif
 
 using remoting::g_npnetscape_funcs;
+using remoting::HostLogHandler;
 using remoting::HostNPScriptObject;
 using remoting::StringFromNPIdentifier;
 
@@ -352,6 +354,12 @@ NPError CreatePlugin(NPMIMEType pluginType,
                      char** argv,
                      NPSavedData* saved) {
   VLOG(2) << "CreatePlugin";
+
+  // Register a global log handler.
+  // The LogMessage registration code is not thread-safe, so we need to perform
+  // this while we're running in a single thread.
+  HostLogHandler::RegisterLogMessageHandler();
+
   HostNPPlugin* plugin = new HostNPPlugin(instance, mode);
   instance->pdata = plugin;
   if (!plugin->Init(argc, argn, argv, saved)) {
@@ -366,6 +374,14 @@ NPError CreatePlugin(NPMIMEType pluginType,
 NPError DestroyPlugin(NPP instance,
                       NPSavedData** save) {
   VLOG(2) << "DestroyPlugin";
+
+  // Normally, we would unregister the global log handler that we registered
+  // in CreatePlugin. However, the LogHandler registration code is not thread-
+  // safe so we could crash if we update (register or unregister) the
+  // LogHandler while it's being read on another thread.
+  // At this point, all our threads should be shutdown, but it's safer to leave
+  // the handler registered until we're completely destroyed.
+
   HostNPPlugin* plugin = PluginFromInstance(instance);
   if (plugin) {
     plugin->Save(save);

remoting/host/plugin/host_script_object.cc

@@ -11,13 +11,13 @@
 #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"
@@ -72,13 +72,6 @@ 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,
@@ -92,20 +85,9 @@ HostNPScriptObject::HostNPScriptObject(
       host_context_(plugin_message_loop_proxy_),
       failed_login_attempts_(0),
       disconnected_event_(true, false),
+      am_currently_logging_(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() {
@@ -115,9 +97,7 @@ HostNPScriptObject::~HostNPScriptObject() {
   // 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();
 
@@ -275,6 +255,7 @@ bool HostNPScriptObject::SetProperty(const std::string& property_name,
   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 " +
@@ -611,40 +592,32 @@ void HostNPScriptObject::OnStateChanged(State state) {
   }
 }
 
-// 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;
+void HostNPScriptObject::PostLogDebugInfo(const std::string& message) {
+  if (plugin_message_loop_proxy_->BelongsToCurrentThread()) {
+    // Make sure we're not currently processing a log message.
+    // We only need to check this if we're on the plugin thread.
+    if (am_currently_logging_)
+      return;
   }
-  if (g_logging_old_handler)
-    return (g_logging_old_handler)(severity, file, line, message_start, str);
-  return false;
+
+  // Always post (even if we're already on the correct thread) so that debug
+  // log messages are shown in the correct 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()) {
+    am_currently_logging_ = true;
     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) {
+      LOG(ERROR) << "ERROR - LogDebugInfo failed\n";
+    }
+    am_currently_logging_ = false;
   }
 }
 

remoting/host/plugin/host_script_object.h

@@ -80,11 +80,10 @@ class HostNPScriptObject : public HostStatusObserver {
       remoting::protocol::ConnectionToClient* client) OVERRIDE;
   virtual void OnShutdown() OVERRIDE;
 
-  // A Log Message Handler that is called after each LOG message has been
-  // processed. This must be of type LogMessageHandlerFunction defined in
-  // base/logging.h.
-  static bool LogToUI(int severity, const char* file, int line,
-                      size_t message_start, const std::string& str);
+  // Post LogDebugInfo to the correct proxy (and thus, on the correct thread).
+  // This should only be called by HostLogHandler. To log to the UI, use the
+  // standard LOG(INFO) and it will be sent to this method.
+  void PostLogDebugInfo(const std::string& message);
 
  private:
   enum State {
@@ -114,6 +113,7 @@ class HostNPScriptObject : public HostStatusObserver {
   void OnStateChanged(State state);
 
   // Call LogDebugInfo handler if there is one.
+  // This must be called on the correct thread.
   void LogDebugInfo(const std::string& message);
 
   // Callbacks invoked during session setup.
@@ -180,6 +180,9 @@ class HostNPScriptObject : public HostStatusObserver {
 
   base::WaitableEvent disconnected_event_;
 
+  // True if we're in the middle of handling a log message.
+  bool am_currently_logging_;
+
   scoped_ptr<policy_hack::NatPolicy> nat_policy_;
 
   // Host the current nat traversal policy setting.
@@ -201,4 +204,4 @@ class HostNPScriptObject : public HostStatusObserver {
 
 DISABLE_RUNNABLE_METHOD_REFCOUNT(remoting::HostNPScriptObject);
 
-#endif  // REMOTING_HOST_HOST_SCRIPT_OBJECT_H_
+#endif  // REMOTING_HOST_PLUGIN_HOST_SCRIPT_OBJECT_H_

remoting/remoting.gyp

@@ -172,6 +172,8 @@
         '../content/common/json_value_serializer.cc',
         '../content/common/json_value_serializer.h',
 
+        'host/plugin/host_log_handler.cc',
+        'host/plugin/host_log_handler.h',
         'host/plugin/host_plugin.cc',
         'host/plugin/host_plugin.def',
         'host/plugin/host_plugin.rc',