ipc/ipc_logging.cc

   1 // Copyright (c) 2010 The Chromium Authors. All rights reserved.
   2 // Use of this source code is governed by a BSD-style license that can be
   3 // found in the LICENSE file.
   4
   5 #include "ipc/ipc_logging.h"
   6
   7 #ifdef IPC_MESSAGE_LOG_ENABLED
   8 #define IPC_MESSAGE_MACROS_LOG_ENABLED
   9 #endif
  10
  11 #include "base/command_line.h"
  12 #include "base/logging.h"
  13 #include "base/message_loop.h"
  14 #include "base/process_util.h"
  15 #include "base/string_number_conversions.h"
  16 #include "base/string_util.h"
  17 #include "base/threading/thread.h"
  18 #include "base/time.h"
  19 #include "ipc/ipc_switches.h"
  20 #include "ipc/ipc_sync_message.h"
  21 #include "ipc/ipc_message_utils.h"
  22
  23 #if defined(OS_POSIX)
  24 #include <unistd.h>
  25 #endif
  26
  27 #ifdef IPC_MESSAGE_LOG_ENABLED
  28
  29 using base::Time;
  30
  31 // IPC::Logging is allocated as a singleton, so we don't need any kind of
  32 // special retention program.
  33 DISABLE_RUNNABLE_METHOD_REFCOUNT(IPC::Logging);
  34
  35 namespace IPC {
  36
  37 const int kLogSendDelayMs = 100;
  38
  39 // We use a pointer to the function table to avoid any linker dependencies on
  40 // all the traits used as IPC message parameters.
  41 LogFunctionMap* Logging::log_function_map_;
  42
  43 Logging::Logging()
  44     : enabled_(false),
  45       enabled_on_stderr_(false),
  46       queue_invoke_later_pending_(false),
  47       sender_(NULL),
  48       main_thread_(MessageLoop::current()),
  49       consumer_(NULL) {
  50 #if defined(OS_WIN)
  51   // getenv triggers an unsafe warning. Simply check how big of a buffer
  52   // would be needed to fetch the value to see if the enviornment variable is
  53   // set.
  54   size_t requiredSize = 0;
  55   getenv_s(&requiredSize, NULL, 0, "CHROME_IPC_LOGGING");
  56   bool logging_env_var_set = (requiredSize != 0);
  57 #else  // !defined(OS_WIN)
  58   bool logging_env_var_set = (getenv("CHROME_IPC_LOGGING") != NULL);
  59 #endif  //defined(OS_WIN)
  60   if (logging_env_var_set) {
  61     enabled_ = true;
  62     enabled_on_stderr_ = true;
  63   }
  64 }
  65
  66 Logging::~Logging() {
  67 }
  68
  69 Logging* Logging::GetInstance() {
  70   return Singleton<Logging>::get();
  71 }
  72
  73 void Logging::SetConsumer(Consumer* consumer) {
  74   consumer_ = consumer;
  75 }
  76
  77 void Logging::Enable() {
  78   enabled_ = true;
  79 }
  80
  81 void Logging::Disable() {
  82   enabled_ = false;
  83 }
  84
  85 void Logging::OnSendLogs() {
  86   queue_invoke_later_pending_ = false;
  87   if (!sender_)
  88     return;
  89
  90   Message* msg = new Message(
  91       MSG_ROUTING_CONTROL, IPC_LOGGING_ID, Message::PRIORITY_NORMAL);
  92   WriteParam(msg, queued_logs_);
  93   queued_logs_.clear();
  94   sender_->Send(msg);
  95 }
  96
  97 void Logging::SetIPCSender(IPC::Message::Sender* sender) {
  98   sender_ = sender;
  99 }
 100
 101 void Logging::OnReceivedLoggingMessage(const Message& message) {
 102   std::vector<LogData> data;
 103   void* iter = NULL;
 104   if (!ReadParam(&message, &iter, &data))
 105     return;
 106
 107   for (size_t i = 0; i < data.size(); ++i) {
 108     Log(data[i]);
 109   }
 110 }
 111
 112 void Logging::OnSendMessage(Message* message, const std::string& channel_id) {
 113   if (!Enabled())
 114     return;
 115
 116   if (message->is_reply()) {
 117     LogData* data = message->sync_log_data();
 118     if (!data)
 119       return;
 120
 121     // This is actually the delayed reply to a sync message.  Create a string
 122     // of the output parameters, add it to the LogData that was earlier stashed
 123     // with the reply, and log the result.
 124     data->channel = channel_id;
 125     GenerateLogData("", *message, data);
 126     Log(*data);
 127     delete data;
 128     message->set_sync_log_data(NULL);
 129   } else {
 130     // If the time has already been set (i.e. by ChannelProxy), keep that time
 131     // instead as it's more accurate.
 132     if (!message->sent_time())
 133       message->set_sent_time(Time::Now().ToInternalValue());
 134   }
 135 }
 136
 137 void Logging::OnPreDispatchMessage(const Message& message) {
 138   message.set_received_time(Time::Now().ToInternalValue());
 139 }
 140
 141 void Logging::OnPostDispatchMessage(const Message& message,
 142                                     const std::string& channel_id) {
 143   if (!Enabled() ||
 144       !message.sent_time() ||
 145       !message.received_time() ||
 146       message.dont_log())
 147     return;
 148
 149   LogData data;
 150   GenerateLogData(channel_id, message, &data);
 151
 152   if (MessageLoop::current() == main_thread_) {
 153     Log(data);
 154   } else {
 155     main_thread_->PostTask(FROM_HERE, NewRunnableMethod(
 156         this, &Logging::Log, data));
 157   }
 158 }
 159
 160 void Logging::GetMessageText(uint32 type, std::string* name,
 161                              const Message* message,
 162                              std::string* params) {
 163   if (!log_function_map_)
 164     return;
 165
 166   LogFunctionMap::iterator it = log_function_map_->find(type);
 167   if (it == log_function_map_->end()) {
 168     if (name) {
 169       *name = "[UNKNOWN MSG ";
 170       *name += base::IntToString(type);
 171       *name += " ]";
 172     }
 173     return;
 174   }
 175
 176   (*it->second)(name, message, params);
 177 }
 178
 179 void Logging::Log(const LogData& data) {
 180   if (consumer_) {
 181     // We're in the browser process.
 182     consumer_->Log(data);
 183   } else {
 184     // We're in the renderer or plugin processes.
 185     if (sender_) {
 186       queued_logs_.push_back(data);
 187       if (!queue_invoke_later_pending_) {
 188         queue_invoke_later_pending_ = true;
 189         MessageLoop::current()->PostDelayedTask(FROM_HERE, NewRunnableMethod(
 190             this, &Logging::OnSendLogs), kLogSendDelayMs);
 191       }
 192     }
 193   }
 194   if (enabled_on_stderr_) {
 195     std::string message_name;
 196     if (data.message_name.empty()) {
 197       message_name = StringPrintf("[unknown type %d]", data.type);
 198     } else {
 199       message_name = data.message_name;
 200     }
 201     fprintf(stderr, "ipc %s %d %s %s %s\n",
 202             data.channel.c_str(),
 203             data.routing_id,
 204             data.flags.c_str(),
 205             message_name.c_str(),
 206             data.params.c_str());
 207   }
 208 }
 209
 210 void GenerateLogData(const std::string& channel, const Message& message,
 211                      LogData* data) {
 212   if (message.is_reply()) {
 213     // "data" should already be filled in.
 214     std::string params;
 215     Logging::GetMessageText(data->type, NULL, &message, &params);
 216
 217     if (!data->params.empty() && !params.empty())
 218       data->params += ", ";
 219
 220     data->flags += " DR";
 221
 222     data->params += params;
 223   } else {
 224     std::string flags;
 225     if (message.is_sync())
 226       flags = "S";
 227
 228     if (message.is_reply())
 229       flags += "R";
 230
 231     if (message.is_reply_error())
 232       flags += "E";
 233
 234     std::string params, message_name;
 235     Logging::GetMessageText(message.type(), &message_name, &message, &params);
 236
 237     data->channel = channel;
 238     data->routing_id = message.routing_id();
 239     data->type = message.type();
 240     data->flags = flags;
 241     data->sent = message.sent_time();
 242     data->receive = message.received_time();
 243     data->dispatch = Time::Now().ToInternalValue();
 244     data->params = params;
 245     data->message_name = message_name;
 246   }
 247 }
 248
 249 }
 250
 251 #endif  // IPC_MESSAGE_LOG_ENABLED