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"
 
 namespace remoting {
 
 // Supported Javascript interface:
 // readonly attribute string accessCode;
 // readonly attribute int accessCodeLifetime;
 // readonly attribute string client;
@@ skipping 34 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 137 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 316 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/31 01:30:16]

We could LOG if we have a boolean member of HostNPScriptObject which we set when
we enter this function, clear when we leave, and test in PostLogDebugInfo,
because PostLogDebugInfo will be on the same thread in that case, so will
correctly know not to post.

That said, I think even testing |is_good| here is probably unnecessary, since
we're never going to see this printf logging anyway, in normal operation.

An alternative would be to un-register this object as logger as soon as calling
the logging callback fails, and then LOG() the fact that it failed; that way we
get normal Chrome LOG() output without any fancy handling.

[garykac, 2011/08/31 23:59:46]

We'd have to only read the flag when we're on the correct thread otherwise we'll
skip LOG messages from other threads that just happened to be be sent while
we're processing another log.
I waffled between deleting it or changing it to a printf. Dave said that he
preferred the printf.

+    }
   }
 }
 
 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(NPObject* localize_func) {
@@ skipping 56 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