Add logging to ExtensionsService, UserScriptMaster,

and PluginChannel to be able to see what happens
when chrome runs extensions headless.

It would be better to modify the existing
IPC::Logging mechanism than add logging to
PluginChannel, so that it could be useful for
debugging other types of IPC problems. But I don't
have time to do that right now.

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

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

7 files changed, 39 insertions, 0 deletions

diff --git a/chrome/browser/extensions/extensions_service.cc b/chrome/browser/extensions/extensions_service.cc
index a8c395c..17c5afe 100644
--- a/chrome/browser/extensions/extensions_service.cc
+++ b/chrome/browser/extensions/extensions_service.cc
@@ -183,6 +183,8 @@ bool ExtensionsServiceBackend::LoadExtensionsFromDirectory(
   if (!file_util::AbsolutePath(&path))
     NOTREACHED();
 
+  LOG(INFO) << "Loading installed extensions...";
+
   // Find all child directories in the install directory and load their
   // manifests. Post errors and results to the frontend.
   scoped_ptr<ExtensionList> extensions(new ExtensionList);
@@ -199,12 +201,17 @@ bool ExtensionsServiceBackend::LoadExtensionsFromDirectory(
       continue;
     }
 
+    LOG(INFO) << "  " << WideToASCII(child_path.BaseName().ToWStringHack()) <<
+       " version: " << version_str;
+
     child_path = child_path.AppendASCII(version_str);
     Extension* extension = LoadExtension(child_path, frontend);
     if (extension)
       extensions->push_back(extension);
   }
 
+  LOG(INFO) << "Done.";
+
   ReportExtensionsLoaded(frontend.get(), extensions.release());
   return true;
 }
@@ -215,6 +222,10 @@ bool ExtensionsServiceBackend::LoadSingleExtension(
   FilePath path = path_in;
   if (!file_util::AbsolutePath(&path))
     NOTREACHED();
+
+  LOG(INFO) << "Loading single extension from " <<
+      WideToASCII(path.BaseName().ToWStringHack());
+
   Extension* extension = LoadExtension(path, frontend);
   if (extension) {
     ExtensionList* extensions = new ExtensionList;
diff --git a/chrome/browser/plugin_process_host.cc b/chrome/browser/plugin_process_host.cc
index b54fe20..15d2317 100644
--- a/chrome/browser/plugin_process_host.cc
+++ b/chrome/browser/plugin_process_host.cc
@@ -409,6 +409,7 @@ bool PluginProcessHost::Init(const WebPluginInfo& info,
     switches::kEnableLogging,
     switches::kDisableLogging,
     switches::kLoggingLevel,
+    switches::kLogPluginMessages,
     switches::kUserDataDir,
     switches::kAllowAllActiveX,
     switches::kEnableDCHECK,
diff --git a/chrome/common/chrome_switches.cc b/chrome/common/chrome_switches.cc
index c142622..43baf87 100644
--- a/chrome/common/chrome_switches.cc
+++ b/chrome/common/chrome_switches.cc
@@ -180,6 +180,9 @@ const wchar_t kDisableLogging[]                = L"disable-logging";
 // INFO = 0, WARNING = 1, LOG_ERROR = 2, LOG_FATAL = 3.
 const wchar_t kLoggingLevel[]                  = L"log-level";
 
+// Make plugin processes log their sent and received messages to LOG(INFO).
+const wchar_t kLogPluginMessages[]             = L"log-plugin-messages";
+
 // Dump any accumualted histograms to the log when browser terminates (requires
 // logging to be enabled to really do anything).  Used by developers and test
 // scripts.
diff --git a/chrome/common/chrome_switches.h b/chrome/common/chrome_switches.h
index 64978c2..f3c76916 100644
--- a/chrome/common/chrome_switches.h
+++ b/chrome/common/chrome_switches.h
@@ -56,6 +56,7 @@ extern const wchar_t kWaitForDebuggerChildren[];
 extern const wchar_t kLogFilterPrefix[];
 extern const wchar_t kEnableLogging[];
 extern const wchar_t kLoggingLevel[];
+extern const wchar_t kLogPluginMessages[];
 
 extern const wchar_t kDumpHistogramsOnExit[];
 extern const wchar_t kDisableLogging[];
diff --git a/chrome/plugin/plugin_channel.cc b/chrome/plugin/plugin_channel.cc
index ab2d508..d9da495 100644
--- a/chrome/plugin/plugin_channel.cc
+++ b/chrome/plugin/plugin_channel.cc
@@ -7,7 +7,9 @@
 #include "chrome/plugin/plugin_channel.h"
 
 #include "chrome/common/plugin_messages.h"
+#include "base/command_line.h"
 #include "base/string_util.h"
+#include "chrome/common/chrome_switches.h"
 #include "chrome/plugin/plugin_process.h"
 #include "chrome/plugin/plugin_thread.h"
 
@@ -34,6 +36,8 @@ PluginChannel* PluginChannel::GetPluginChannel(
 PluginChannel::PluginChannel() : in_send_(0) {
   SendUnblockingOnlyDuringDispatch();
   PluginProcess::current()->AddRefProcess();
+  const CommandLine* command_line = CommandLine::ForCurrentProcess();
+  log_messages_ = command_line->HasSwitch(switches::kLogPluginMessages);
 }
 
 PluginChannel::~PluginChannel() {
@@ -42,11 +46,23 @@ PluginChannel::~PluginChannel() {
 
 bool PluginChannel::Send(IPC::Message* msg) {
   in_send_++;
+  if (log_messages_) {
+    LOG(INFO) << "sending message @" << msg << " on channel @" << this
+              << " with type " << msg->type();
+  }
   bool result = PluginChannelBase::Send(msg);
   in_send_--;
   return result;
 }
 
+void PluginChannel::OnMessageReceived(const IPC::Message& msg) {
+  if (log_messages_) {
+    LOG(INFO) << "received message @" << &msg << " on channel @" << this
+              << " with type " << msg.type();
+  }
+  PluginChannelBase::OnMessageReceived(msg);
+}
+
 void PluginChannel::OnControlMessageReceived(const IPC::Message& msg) {
   IPC_BEGIN_MESSAGE_MAP(PluginChannel, msg)
     IPC_MESSAGE_HANDLER(PluginMsg_CreateInstance, OnCreateInstance)
diff --git a/chrome/plugin/plugin_channel.h b/chrome/plugin/plugin_channel.h
index ba37616..4802a6e 100644
--- a/chrome/plugin/plugin_channel.h
+++ b/chrome/plugin/plugin_channel.h
@@ -22,6 +22,7 @@ class PluginChannel : public PluginChannelBase {
   ~PluginChannel();
 
   virtual bool Send(IPC::Message* msg);
+  virtual void OnMessageReceived(const IPC::Message& message);
 
   HANDLE renderer_handle() { return renderer_handle_.Get(); }
   int GenerateRouteID();
@@ -52,6 +53,7 @@ class PluginChannel : public PluginChannelBase {
   ScopedHandle renderer_handle_;
 
   int in_send_;  // Tracks if we're in a Send call.
+  bool log_messages_;  // True if we should log sent and received messages.
 
   DISALLOW_EVIL_CONSTRUCTORS(PluginChannel);
 };
diff --git a/chrome/renderer/user_script_slave.cc b/chrome/renderer/user_script_slave.cc
index cd3951a..36d366d 100644
--- a/chrome/renderer/user_script_slave.cc
+++ b/chrome/renderer/user_script_slave.cc
@@ -119,5 +119,10 @@ bool UserScriptSlave::InjectScripts(WebFrame* frame,
     HISTOGRAM_TIMES("UserScripts:DocEnd:Time", timer.Elapsed());
   }
 
+  if (num_matched > 0) {
+    LOG(INFO) << "Injected " << num_matched << " scripts into " <<
+        frame->GetURL().spec();
+  }
+
   return true;
 }