Enhance plugin load debug logging. This adds more logging for

debug-plugin-loading mode and uses LOG_IF consistently (I thought it would be
more understandable to have the condition explicit rather than some extra macro
that would now have to be moved to a common header file).

TEST=none
BUG=none
Review URL: http://codereview.chromium.org/2799032

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

7 files changed, 76 insertions, 34 deletions

diff --git a/webkit/glue/plugins/plugin_lib.cc b/webkit/glue/plugins/plugin_lib.cc
index dfc6345..a79513d 100644
--- a/webkit/glue/plugins/plugin_lib.cc
+++ b/webkit/glue/plugins/plugin_lib.cc
@@ -170,8 +170,11 @@ bool PluginLib::Load() {
 
   if (!internal_) {
     library = base::LoadNativeLibrary(web_plugin_info_.path);
-    if (library == 0)
+    if (library == 0) {
+      LOG_IF(INFO, PluginList::DebugPluginLoading())
+          << "Couldn't load plugin " << web_plugin_info_.path.value();
       return rv;
+    }
 
 #if defined(OS_MACOSX)
     // According to the WebKit source, QuickTime at least requires us to call
@@ -217,10 +220,17 @@ bool PluginLib::Load() {
   }
 
   if (!internal_) {
-    if (rv)
+    if (rv) {
+      LOG_IF(INFO, PluginList::DebugPluginLoading())
+          << "Plugin " << web_plugin_info_.path.value()
+          << " loaded successfully.";
       library_ = library;
-    else
+    } else {
+      LOG_IF(INFO, PluginList::DebugPluginLoading())
+          << "Plugin " << web_plugin_info_.path.value()
+          << " failed to load, unloading.";
       base::UnloadNativeLibrary(library);
+    }
   }
 
   return rv;
@@ -276,11 +286,17 @@ void PluginLib::Unload() {
       FreePluginLibraryTask* free_library_task =
           new FreePluginLibraryTask(skip_unload_ ? NULL : library_,
                                     entry_points_.np_shutdown);
+      LOG_IF(INFO, PluginList::DebugPluginLoading())
+          << "Scheduling delayed unload for plugin "
+          << web_plugin_info_.path.value();
       MessageLoop::current()->PostTask(FROM_HERE, free_library_task);
     } else {
       Shutdown();
-      if (!skip_unload_)
+      if (!skip_unload_) {
+        LOG_IF(INFO, PluginList::DebugPluginLoading())
+            << "Unloading plugin " << web_plugin_info_.path.value();
         base::UnloadNativeLibrary(library_);
+      }
     }
 
     library_ = NULL;
diff --git a/webkit/glue/plugins/plugin_lib_posix.cc b/webkit/glue/plugins/plugin_lib_posix.cc
index 0bf7786..dbc64ed 100644
--- a/webkit/glue/plugins/plugin_lib_posix.cc
+++ b/webkit/glue/plugins/plugin_lib_posix.cc
@@ -28,6 +28,8 @@
 
 namespace {
 
+using NPAPI::PluginList;
+
 // Copied from nsplugindefs.h instead of including the file since it has a bunch
 // of dependencies.
 enum nsPluginVariable {
@@ -116,10 +118,16 @@ void UnwrapNSPluginWrapper(void **dl, FilePath* unwrapped_path) {
   if (!newdl) {
     // We couldn't load the unwrapped plugin for some reason, despite
     // being able to load the wrapped one.  Just use the wrapped one.
+    LOG_IF(INFO, PluginList::DebugPluginLoading())
+        << "Could not use unwrapped nspluginwrapper plugin "
+        << unwrapped_path->value() << ", using the wrapped one.";
     return;
   }
 
   // Unload the wrapped plugin, and use the wrapped plugin instead.
+  LOG_IF(INFO, PluginList::DebugPluginLoading())
+      << "Using unwrapped version " << unwrapped_path->value()
+      << " of nspluginwrapper-wrapped plugin.";
   base::UnloadNativeLibrary(*dl);
   *dl = newdl;
   *unwrapped_path = path;
@@ -135,12 +143,20 @@ bool PluginLib::ReadWebPluginInfo(const FilePath& filename,
   // http://mxr.mozilla.org/firefox/source/modules/plugin/base/src/nsPluginsDirUnix.cpp
 
   // Skip files that aren't appropriate for our architecture.
-  if (!ELFMatchesCurrentArchitecture(filename))
+  if (!ELFMatchesCurrentArchitecture(filename)) {
+    LOG_IF(INFO, PluginList::DebugPluginLoading())
+        << "Skipping plugin " << filename.value()
+        << " because it doesn't match the current architecture.";
     return false;
+  }
 
   void* dl = base::LoadNativeLibrary(filename);
-  if (!dl)
+  if (!dl) {
+    LOG_IF(INFO, PluginList::DebugPluginLoading())
+        << "While reading plugin info, unable to load library "
+        << filename.value() << ", skipping.";
     return false;
+  }
 
   info->path = filename;
   info->enabled = true;
@@ -176,6 +192,15 @@ bool PluginLib::ReadWebPluginInfo(const FilePath& filename,
     NP_GetValue(NULL, nsPluginVariable_DescriptionString, &description);
     if (description)
       info->desc = UTF8ToUTF16(description);
+
+    LOG_IF(INFO, PluginList::DebugPluginLoading())
+        << "Got info for plugin " << filename.value()
+        << " Name = \"" << UTF16ToUTF8(info->name)
+        << "\", Description = \"" << UTF16ToUTF8(info->desc) << "\".";
+  } else {
+    LOG_IF(INFO, PluginList::DebugPluginLoading())
+        << "Plugin " << filename.value()
+        << " has no GetValue() and probably won't work.";
   }
 
   // Intentionally not unloading the plugin here, it can lead to crashes.
diff --git a/webkit/glue/plugins/plugin_list.cc b/webkit/glue/plugins/plugin_list.cc
index 1d164ea..1ec170c 100644
--- a/webkit/glue/plugins/plugin_list.cc
+++ b/webkit/glue/plugins/plugin_list.cc
@@ -6,16 +6,18 @@
 
 #include <algorithm>
 
+#include "base/command_line.h"
 #include "base/lazy_instance.h"
 #include "base/logging.h"
 #include "base/string_util.h"
 #include "base/utf_string_conversions.h"
 #include "base/time.h"
+#include "googleurl/src/gurl.h"
 #include "net/base/mime_util.h"
 #include "webkit/glue/plugins/plugin_constants_win.h"
 #include "webkit/glue/plugins/plugin_lib.h"
+#include "webkit/glue/plugins/plugin_switches.h"
 #include "webkit/glue/webkit_glue.h"
-#include "googleurl/src/gurl.h"
 
 namespace NPAPI {
 
@@ -26,6 +28,12 @@ PluginList* PluginList::Singleton() {
   return g_singleton.Pointer();
 }
 
+// static
+bool PluginList::DebugPluginLoading() {
+  return CommandLine::ForCurrentProcess()->HasSwitch(
+      switches::kDebugPluginLoading);
+}
+
 bool PluginList::PluginsLoaded() {
   AutoLock lock(lock_);
   return plugins_loaded_;
diff --git a/webkit/glue/plugins/plugin_list.h b/webkit/glue/plugins/plugin_list.h
index f018346..7187ae2 100644
--- a/webkit/glue/plugins/plugin_list.h
+++ b/webkit/glue/plugins/plugin_list.h
@@ -73,6 +73,10 @@ class PluginList {
   // Gets the one instance of the PluginList.
   static PluginList* Singleton();
 
+  // Returns true if we're in debug-plugin-loading mode. This is controlled
+  // by a command line switch.
+  static bool DebugPluginLoading();
+
   // Returns true iff the plugin list has been loaded already.
   bool PluginsLoaded();
 
diff --git a/webkit/glue/plugins/plugin_list_posix.cc b/webkit/glue/plugins/plugin_list_posix.cc
index b787cb0..1ad742d 100644
--- a/webkit/glue/plugins/plugin_list_posix.cc
+++ b/webkit/glue/plugins/plugin_list_posix.cc
@@ -4,24 +4,13 @@
 
 #include "webkit/glue/plugins/plugin_list.h"
 
-#include "base/command_line.h"
 #include "base/file_util.h"
 #include "base/path_service.h"
 #include "base/string_util.h"
 #include "build/build_config.h"
-#include "webkit/glue/plugins/plugin_switches.h"
 
 namespace {
 
-// Return true if we're in debug-plugin-loading mode.
-bool DebugPluginLoading() {
-  return CommandLine::ForCurrentProcess()->HasSwitch(
-      switches::kDebugPluginLoading);
-}
-
-// Shorthand way of logging plugin load status.
-#define PLUG_LOG if (DebugPluginLoading()) LOG(INFO)
-
 // We build up a list of files and mtimes so we can sort them.
 typedef std::pair<FilePath, base::Time> FileAndTime;
 typedef std::vector<FileAndTime> FileTimeList;
@@ -159,16 +148,19 @@ void PluginList::LoadPluginsFromDir(const FilePath& dir_path,
     // symlinks.
     FilePath orig_path = path;
     file_util::AbsolutePath(&path);
-    PLUG_LOG << "Resolved " << orig_path.value() << " -> " << path.value();
+    LOG_IF(INFO, PluginList::DebugPluginLoading())
+        << "Resolved " << orig_path.value() << " -> " << path.value();
 
     if (visited_plugins->find(path) != visited_plugins->end()) {
-      PLUG_LOG << "Skipping duplicate instance of " << path.value();
+      LOG_IF(INFO, PluginList::DebugPluginLoading())
+          << "Skipping duplicate instance of " << path.value();
       continue;
     }
     visited_plugins->insert(path);
 
     if (IsBlacklistedPlugin(path)) {
-      PLUG_LOG << "Skipping blacklisted plugin " << path.value();
+      LOG_IF(INFO, PluginList::DebugPluginLoading())
+          << "Skipping blacklisted plugin " << path.value();
       continue;
     }
 
@@ -208,10 +200,12 @@ void PluginList::LoadPluginsFromDir(const FilePath& dir_path,
 
 bool PluginList::ShouldLoadPlugin(const WebPluginInfo& info,
                                   std::vector<WebPluginInfo>* plugins) {
-  PLUG_LOG << "Considering " << info.path.value() << " (" << info.name << ")";
+  LOG_IF(INFO, PluginList::DebugPluginLoading())
+      << "Considering " << info.path.value() << " (" << info.name << ")";
 
   if (IsUndesirablePlugin(info)) {
-    PLUG_LOG << info.path.value() << " is undesirable.";
+    LOG_IF(INFO, PluginList::DebugPluginLoading())
+        << info.path.value() << " is undesirable.";
 
     // See if we have a better version of this plugin.
     for (size_t i = 0; i < plugins->size(); ++i) {
@@ -219,8 +213,9 @@ bool PluginList::ShouldLoadPlugin(const WebPluginInfo& info,
           !IsUndesirablePlugin(plugins->at(i))) {
         // Skip the current undesirable one so we can use the better one
         // we just found.
-        PLUG_LOG << "Skipping " << info.path.value() << ", preferring "
-                 << plugins->at(i).path.value();
+        LOG_IF(INFO, PluginList::DebugPluginLoading())
+            << "Skipping " << info.path.value() << ", preferring "
+            << plugins->at(i).path.value();
         return false;
       }
     }
@@ -228,7 +223,8 @@ bool PluginList::ShouldLoadPlugin(const WebPluginInfo& info,
 
   // TODO(evanm): prefer the newest version of flash, etc. here?
 
-  PLUG_LOG << "Using " << info.path.value();
+  LOG_IF(INFO, PluginList::DebugPluginLoading())
+      << "Using " << info.path.value();
 
   return true;
 }
diff --git a/webkit/glue/plugins/plugin_switches.cc b/webkit/glue/plugins/plugin_switches.cc
index cc76917..eb5c958 100644
--- a/webkit/glue/plugins/plugin_switches.cc
+++ b/webkit/glue/plugins/plugin_switches.cc
@@ -9,9 +9,7 @@ namespace switches {
 // Enables the testing interface for PPAPI.
 const char kEnablePepperTesting[] = "enable-pepper-testing";
 
-#if defined(OS_POSIX)
 // Dumps extra logging about plugin loading to the log file.
 const char kDebugPluginLoading[] = "debug-plugin-loading";
-#endif
 
 }  // namespace switches
diff --git a/webkit/glue/plugins/plugin_switches.h b/webkit/glue/plugins/plugin_switches.h
index 8c99704..772c0476 100644
--- a/webkit/glue/plugins/plugin_switches.h
+++ b/webkit/glue/plugins/plugin_switches.h
@@ -5,15 +5,10 @@
 #ifndef WEBKIT_GLUE_PLUGINS_PLUGIN_SWITCHES_H_
 #define WEBKIT_GLUE_PLUGINS_PLUGIN_SWITCHES_H_
 
-#include "build/build_config.h"
-
 namespace switches {
 
-extern const char kEnablePepperTesting[];
-
-#if defined(OS_POSIX)
 extern const char kDebugPluginLoading[];
-#endif
+extern const char kEnablePepperTesting[];
 
 }  // namespace switches