POSIX: basic IPC logging

For the moment, we enable IPC logging with an environment variable
(CHROME_IPC_LOGGING) and log everything to stderr.

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


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

7 files changed, 82 insertions, 42 deletions

diff --git a/chrome/common/common.scons b/chrome/common/common.scons
index 832485f..5824335 100644
--- a/chrome/common/common.scons
+++ b/chrome/common/common.scons
@@ -232,7 +232,6 @@ if not env.Bit('windows'):
       'gfx/emf.cc',
       'gfx/icon_util.cc',
       'gfx/path.cc',
-      'ipc_logging.cc',
       'os_exchange_data.cc',
       'process_watcher.cc',
   )
diff --git a/chrome/common/ipc_channel_proxy.cc b/chrome/common/ipc_channel_proxy.cc
index 11fdb9b..6173135 100644
--- a/chrome/common/ipc_channel_proxy.cc
+++ b/chrome/common/ipc_channel_proxy.cc
@@ -5,19 +5,11 @@
 #include "base/message_loop.h"
 #include "base/thread.h"
 #include "chrome/common/ipc_channel_proxy.h"
-#if defined(OS_WIN)
-// TODO(playmobil): remove ifdef once ObjectWatcher is ported
 #include "chrome/common/ipc_logging.h"
-#endif
 #include "chrome/common/ipc_message_utils.h"
 
 namespace IPC {
 
-#if defined(OS_POSIX)
-// TODO(playmobil): remove once ObjectWatcher is ported
-#undef IPC_MESSAGE_LOG_ENABLED
-#endif
-
 //-----------------------------------------------------------------------------
 
 ChannelProxy::Context::Context(Channel::Listener* listener,
diff --git a/chrome/common/ipc_logging.cc b/chrome/common/ipc_logging.cc
index c9874b7..6cb401f 100644
--- a/chrome/common/ipc_logging.cc
+++ b/chrome/common/ipc_logging.cc
@@ -4,17 +4,34 @@
 
 #include "chrome/common/ipc_logging.h"
 
+#if defined(OS_POSIX)
+#ifdef IPC_MESSAGE_LOG_ENABLED
+// This will cause render_messages.h etc to define ViewMsgLog and friends.
+#define IPC_MESSAGE_MACROS_LOG_ENABLED
+#endif
+#endif
+
 #include "base/command_line.h"
 #include "base/logging.h"
 #include "base/message_loop.h"
 #include "base/string_util.h"
 #include "base/thread.h"
 #include "base/time.h"
+#include "base/waitable_event.h"
+#include "base/waitable_event_watcher.h"
 #include "chrome/common/chrome_switches.h"
 #include "chrome/common/ipc_sync_message.h"
 #include "chrome/common/ipc_message_utils.h"
 #include "chrome/common/render_messages.h"
+#if defined(OS_WIN)
+// TODO(port): These messages will need to be ported at some point
 #include "chrome/common/plugin_messages.h"
+#endif
+
+#if defined(OS_POSIX)
+#include "base/string_util.h"
+#include <unistd.h>
+#endif
 
 #ifdef IPC_MESSAGE_LOG_ENABLED
 
@@ -41,14 +58,17 @@ Logging::Logging()
     : logging_event_on_(NULL),
       logging_event_off_(NULL),
       enabled_(false),
-      sender_(NULL),
-      consumer_(NULL),
       queue_invoke_later_pending_(false),
-      main_thread_(MessageLoop::current()) {
+      sender_(NULL),
+      main_thread_(MessageLoop::current()),
+      consumer_(NULL) {
   // Create an event for this browser instance that's set when logging is
   // enabled, so child processes can know when logging is enabled.
-  int browser_pid;
 
+#if defined(OS_WIN)
+  // On Windows we have a couple of named events which switch logging on and
+  // off.
+  int browser_pid;
   const CommandLine& parsed_command_line = *CommandLine::ForCurrentProcess();
   std::wstring process_type =
     parsed_command_line.GetSwitchValue(switches::kProcessType);
@@ -63,18 +83,23 @@ Logging::Logging()
   }
 
   std::wstring event_name = GetEventName(browser_pid, true);
-  logging_event_on_ = CreateEvent(NULL, TRUE, FALSE, event_name.c_str());
+  logging_event_on_.reset(new base::WaitableEvent(
+      CreateEvent(NULL, TRUE, FALSE, event_name.c_str())));
 
   event_name = GetEventName(browser_pid, false);
-  logging_event_off_ = CreateEvent(NULL, TRUE, FALSE, event_name.c_str());
+  logging_event_off_.reset(new base::WaitableEvent(
+      CreateEvent(NULL, TRUE, FALSE, event_name.c_str())));
 
   RegisterWaitForEvent(true);
+#elif defined(OS_POSIX)
+  if (getenv("CHROME_IPC_LOGGING"))
+    enabled_ = true;
+  SetLoggerFunctions(g_log_function_mapping);
+#endif
 }
 
 Logging::~Logging() {
   watcher_.StopWatching();
-  CloseHandle(logging_event_on_);
-  CloseHandle(logging_event_off_);
 }
 
 Logging* Logging::current() {
@@ -84,11 +109,11 @@ Logging* Logging::current() {
 void Logging::RegisterWaitForEvent(bool enabled) {
   watcher_.StopWatching();
   watcher_.StartWatching(
-      enabled ? logging_event_on_ : logging_event_off_, this);
+      enabled ? logging_event_on_.get() : logging_event_off_.get(), this);
 }
 
-void Logging::OnObjectSignaled(HANDLE object) {
-  enabled_ = object == logging_event_on_;
+void Logging::OnWaitableEventSignaled(base::WaitableEvent* event) {
+  enabled_ = event == logging_event_on_.get();
   RegisterWaitForEvent(!enabled_);
 }
 
@@ -96,9 +121,11 @@ void Logging::SetLoggerFunctions(LogFunction *functions) {
   log_function_mapping_ = functions;
 }
 
+#if defined(OS_WIN)
 std::wstring Logging::GetEventName(bool enabled) {
   return current()->GetEventName(GetCurrentProcessId(), enabled);
 }
+#endif
 
 std::wstring Logging::GetEventName(int browser_pid, bool enabled) {
   std::wstring result = StringPrintf(kLoggingEventName, browser_pid);
@@ -111,17 +138,13 @@ void Logging::SetConsumer(Consumer* consumer) {
 }
 
 void Logging::Enable() {
-  ResetEvent(logging_event_off_);
-  SetEvent(logging_event_on_);
+  logging_event_off_->Reset();
+  logging_event_on_->Signal();
 }
 
 void Logging::Disable() {
-  ResetEvent(logging_event_on_);
-  SetEvent(logging_event_off_);
-}
-
-inline bool Logging::Enabled() const {
-  return enabled_;
+  logging_event_on_->Reset();
+  logging_event_off_->Signal();
 }
 
 void Logging::OnSendLogs() {
@@ -182,7 +205,11 @@ void Logging::OnPreDispatchMessage(const Message& message) {
 
 void Logging::OnPostDispatchMessage(const Message& message,
                                     const std::wstring& channel_id) {
-  if (!Enabled() || !message.sent_time() || message.dont_log())
+  if (!Enabled() ||
+#if defined(OS_WIN)
+      !message.sent_time() ||
+#endif
+      message.dont_log())
     return;
 
   LogData data;
@@ -212,6 +239,7 @@ void Logging::GetMessageText(uint16 type, std::wstring* name,
 }
 
 void Logging::Log(const LogData& data) {
+#if defined(OS_WIN)
   if (consumer_) {
     // We're in the browser process.
     consumer_->Log(data);
@@ -226,6 +254,15 @@ void Logging::Log(const LogData& data) {
       }
     }
   }
+#elif defined(OS_POSIX)
+  // On POSIX, for now, we just dump the log to stderr
+  fprintf(stderr, "ipc %s %d %s %s %s\n",
+          WideToUTF8(data.channel).c_str(),
+          data.type,
+          WideToUTF8(data.flags).c_str(),
+          WideToUTF8(data.message_name).c_str(),
+          WideToUTF8(data.params).c_str());
+#endif
 }
 
 void GenerateLogData(const std::wstring& channel, const Message& message,
@@ -252,8 +289,8 @@ void GenerateLogData(const std::wstring& channel, const Message& message,
     if (message.is_reply_error())
       flags += L"E";
 
-    std::wstring params;
-    Logging::GetMessageText(message.type(), NULL, &message, &params);
+    std::wstring params, message_name;
+    Logging::GetMessageText(message.type(), &message_name, &message, &params);
 
     data->channel = channel;
     data->type = message.type();
@@ -262,6 +299,7 @@ void GenerateLogData(const std::wstring& channel, const Message& message,
     data->receive = message.received_time();
     data->dispatch = Time::Now().ToInternalValue();
     data->params = params;
+    data->message_name = message_name;
   }
 }
 
diff --git a/chrome/common/ipc_logging.h b/chrome/common/ipc_logging.h
index 5d4016d..06a687b 100644
--- a/chrome/common/ipc_logging.h
+++ b/chrome/common/ipc_logging.h
@@ -10,8 +10,8 @@
 #ifdef IPC_MESSAGE_LOG_ENABLED
 
 #include "base/lock.h"
-#include "base/object_watcher.h"
 #include "base/singleton.h"
+#include "base/waitable_event_watcher.h"
 #include "chrome/common/ipc_message_utils.h"
 
 class MessageLoop;
@@ -23,7 +23,7 @@ class Message;
 // One instance per process.  Needs to be created on the main thread (the UI
 // thread in the browser) but OnPreDispatchMessage/OnPostDispatchMessage
 // can be called on other threads.
-class Logging : public base::ObjectWatcher::Delegate {
+class Logging : public base::WaitableEventWatcher::Delegate {
  public:
   // Implemented by consumers of log messages.
   class Consumer {
@@ -38,7 +38,7 @@ class Logging : public base::ObjectWatcher::Delegate {
 
   void Enable();
   void Disable();
-  bool inline Enabled() const;
+  bool Enabled() const { return enabled_; }
 
   // Called by child processes to give the logger object the channel to send
   // logging data to the browser process.
@@ -64,8 +64,8 @@ class Logging : public base::ObjectWatcher::Delegate {
   static void GetMessageText(uint16 type, std::wstring* name,
                              const Message* message, std::wstring* params);
 
-  // ObjectWatcher::Delegate implementation
-  void OnObjectSignaled(HANDLE object);
+  // WaitableEventWatcher::Delegate implementation
+  void OnWaitableEventSignaled(base::WaitableEvent* event);
 
   typedef void (*LogFunction)(uint16 type,
                              std::wstring* name,
@@ -84,10 +84,10 @@ class Logging : public base::ObjectWatcher::Delegate {
 
   void RegisterWaitForEvent(bool enabled);
 
-  base::ObjectWatcher watcher_;
+  base::WaitableEventWatcher watcher_;
 
-  HANDLE logging_event_on_;
-  HANDLE logging_event_off_;
+  scoped_ptr<base::WaitableEvent> logging_event_on_;
+  scoped_ptr<base::WaitableEvent> logging_event_off_;
   bool enabled_;
 
   std::vector<LogData> queued_logs_;
diff --git a/chrome/common/ipc_message.h b/chrome/common/ipc_message.h
index 8aedbe3..0601ed6 100644
--- a/chrome/common/ipc_message.h
+++ b/chrome/common/ipc_message.h
@@ -11,12 +11,11 @@
 #include "base/pickle.h"
 #include "testing/gtest/include/gtest/gtest_prod.h"
 
-#if defined(OS_WIN)
-// TODO(port): IPC message logging hasn't been ported to other platforms yet.
 #ifndef NDEBUG
 #define IPC_MESSAGE_LOG_ENABLED
 #endif
-#elif defined(OS_POSIX)
+
+#if defined(OS_POSIX)
 #include "chrome/common/descriptor_set_posix.h"
 #endif
 
diff --git a/chrome/common/ipc_message_utils.h b/chrome/common/ipc_message_utils.h
index e7dd7e3..a87a594 100644
--- a/chrome/common/ipc_message_utils.h
+++ b/chrome/common/ipc_message_utils.h
@@ -867,6 +867,7 @@ struct LogData {
                   // OnMessageReceived).
   int64 dispatch;  // Time after it was dispatched (i.e. after calling
                    // OnMessageReceived).
+  std::wstring message_name;
   std::wstring params;
 };
 
diff --git a/chrome/common/ipc_tests.scons b/chrome/common/ipc_tests.scons
index a9dd518..3f2c3fb 100644
--- a/chrome/common/ipc_tests.scons
+++ b/chrome/common/ipc_tests.scons
@@ -8,6 +8,8 @@ env = env.Clone()
 
 env.SConscript([
     '$BASE_DIR/using_base.scons',
+    '$BASE_DIR/gfx/using_base_gfx.scons',  # needed for logging
+    '$CHROME_SRC_DIR/build/using_googleurl.scons',  # needed for logging
     '$BREAKPAD_DIR/using_breakpad.scons',
     '$CHROME_DIR/third_party/wtl/using_wtl.scons',
     '$GTEST_DIR/../using_gtest.scons',
@@ -15,11 +17,20 @@ env.SConscript([
     '$LIBJPEG_DIR/using_libjpeg.scons',
     '$LIBPNG_DIR/using_libpng.scons',
     '$LIBXML_DIR/using_libxml.scons',
+    '$NET_DIR/using_net.scons',  # needed for logging
     '$NPAPI_DIR/using_npapi.scons',
     '$SKIA_DIR/using_skia.scons',
     '$ZLIB_DIR/using_zlib.scons',
 ], {'env':env})
 
+# needed for logging
+env.Append(
+  LIBS = [
+    'glue',
+    'WTF',
+  ],
+)
+
 if env.Bit('posix'):
   env.SConscript([
       '$LIBEVENT_DIR/using_libevent.scons',