ipc/ipc_logging.cc

   1 // Copyright (c) 2012 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/bind.h"
  12 #include "base/bind_helpers.h"
  13 #include "base/command_line.h"
  14 #include "base/location.h"
  15 #include "base/logging.h"
  16 #include "base/message_loop.h"
  17 #include "base/process_util.h"
  18 #include "base/string_number_conversions.h"
  19 #include "base/string_util.h"
  20 #include "base/threading/thread.h"
  21 #include "base/time.h"
  22 #include "ipc/ipc_switches.h"
  23 #include "ipc/ipc_sync_message.h"
  24 #include "ipc/ipc_message_utils.h"
  25
  26 #if defined(OS_POSIX)
  27 #include <unistd.h>
  28 #endif
  29
  30 #ifdef IPC_MESSAGE_LOG_ENABLED
  31
  32 using base::Time;
  33
  34 namespace IPC {
  35
  36 const int kLogSendDelayMs = 100;
  37
  38 // We use a pointer to the function table to avoid any linker dependencies on
  39 // all the traits used as IPC message parameters.
  40 LogFunctionMap* Logging::log_function_map_;
  41
  42 Logging::Logging()
  43     : enabled_(false),
  44       enabled_on_stderr_(false),
  45       enabled_color_(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   if (requiredSize <= 6) {
  58     char buffer[6];
  59     getenv_s(&requiredSize, buffer, sizeof(buffer), "CHROME_IPC_LOGGING");
  60     if (requiredSize && !strncmp("color", buffer, 6))
  61       enabled_color_ = true;
  62   }
  63 #else  // !defined(OS_WIN)
  64   const char* ipc_logging = getenv("CHROME_IPC_LOGGING");
  65   bool logging_env_var_set = (ipc_logging != NULL);
  66   if (ipc_logging && !strcmp(ipc_logging, "color"))
  67     enabled_color_ = true;
  68 #endif  //defined(OS_WIN)
  69   if (logging_env_var_set) {
  70     enabled_ = true;
  71     enabled_on_stderr_ = true;
  72   }
  73 }
  74
  75 Logging::~Logging() {
  76 }
  77
  78 Logging* Logging::GetInstance() {
  79   return Singleton<Logging>::get();
  80 }
  81
  82 void Logging::SetConsumer(Consumer* consumer) {
  83   consumer_ = consumer;
  84 }
  85
  86 void Logging::Enable() {
  87   enabled_ = true;
  88 }
  89
  90 void Logging::Disable() {
  91   enabled_ = false;
  92 }
  93
  94 void Logging::OnSendLogs() {
  95   queue_invoke_later_pending_ = false;
  96   if (!sender_)
  97     return;
  98
  99   Message* msg = new Message(
 100       MSG_ROUTING_CONTROL, IPC_LOGGING_ID, Message::PRIORITY_NORMAL);
 101   WriteParam(msg, queued_logs_);
 102   queued_logs_.clear();
 103   sender_->Send(msg);
 104 }
 105
 106 void Logging::SetIPCSender(IPC::Message::Sender* sender) {
 107   sender_ = sender;
 108 }
 109
 110 void Logging::OnReceivedLoggingMessage(const Message& message) {
 111   std::vector<LogData> data;
 112   void* iter = NULL;
 113   if (!ReadParam(&message, &iter, &data))
 114     return;
 115
 116   for (size_t i = 0; i < data.size(); ++i) {
 117     Log(data[i]);
 118   }
 119 }
 120
 121 void Logging::OnSendMessage(Message* message, const std::string& channel_id) {
 122   if (!Enabled())
 123     return;
 124
 125   if (message->is_reply()) {
 126     LogData* data = message->sync_log_data();
 127     if (!data)
 128       return;
 129
 130     // This is actually the delayed reply to a sync message.  Create a string
 131     // of the output parameters, add it to the LogData that was earlier stashed
 132     // with the reply, and log the result.
 133     data->channel = channel_id;
 134     GenerateLogData("", *message, data, true);
 135     Log(*data);
 136     delete data;
 137     message->set_sync_log_data(NULL);
 138   } else {
 139     // If the time has already been set (i.e. by ChannelProxy), keep that time
 140     // instead as it's more accurate.
 141     if (!message->sent_time())
 142       message->set_sent_time(Time::Now().ToInternalValue());
 143   }
 144 }
 145
 146 void Logging::OnPreDispatchMessage(const Message& message) {
 147   message.set_received_time(Time::Now().ToInternalValue());
 148 }
 149
 150 void Logging::OnPostDispatchMessage(const Message& message,
 151                                     const std::string& channel_id) {
 152   if (!Enabled() ||
 153       !message.sent_time() ||
 154       !message.received_time() ||
 155       message.dont_log())
 156     return;
 157
 158   LogData data;
 159   GenerateLogData(channel_id, message, &data, true);
 160
 161   if (MessageLoop::current() == main_thread_) {
 162     Log(data);
 163   } else {
 164     main_thread_->PostTask(
 165         FROM_HERE, base::Bind(&Logging::Log, base::Unretained(this), data));
 166   }
 167 }
 168
 169 void Logging::GetMessageText(uint32 type, std::string* name,
 170                              const Message* message,
 171                              std::string* params) {
 172   if (!log_function_map_)
 173     return;
 174
 175   LogFunctionMap::iterator it = log_function_map_->find(type);
 176   if (it == log_function_map_->end()) {
 177     if (name) {
 178       *name = "[UNKNOWN MSG ";
 179       *name += base::IntToString(type);
 180       *name += " ]";
 181     }
 182     return;
 183   }
 184
 185   (*it->second)(name, message, params);
 186 }
 187
 188 const char* Logging::ANSIEscape(ANSIColor color) {
 189   if (!enabled_color_)
 190     return "";
 191   switch (color) {
 192     case ANSI_COLOR_RESET:
 193       return "\033[m";
 194     case ANSI_COLOR_BLACK:
 195       return "\033[0;30m";
 196     case ANSI_COLOR_RED:
 197       return "\033[0;31m";
 198     case ANSI_COLOR_GREEN:
 199       return "\033[0;32m";
 200     case ANSI_COLOR_YELLOW:
 201       return "\033[0;33m";
 202     case ANSI_COLOR_BLUE:
 203       return "\033[0;34m";
 204     case ANSI_COLOR_MAGENTA:
 205       return "\033[0;35m";
 206     case ANSI_COLOR_CYAN:
 207       return "\033[0;36m";
 208     case ANSI_COLOR_WHITE:
 209       return "\033[0;37m";
 210   }
 211   return "";
 212 }
 213
 214 Logging::ANSIColor Logging::DelayColor(double delay) {
 215   if (delay < 0.1)
 216     return ANSI_COLOR_GREEN;
 217   if (delay < 0.25)
 218     return ANSI_COLOR_BLACK;
 219   if (delay < 0.5)
 220     return ANSI_COLOR_YELLOW;
 221   return ANSI_COLOR_RED;
 222 }
 223
 224 void Logging::Log(const LogData& data) {
 225   if (consumer_) {
 226     // We're in the browser process.
 227     consumer_->Log(data);
 228   } else {
 229     // We're in the renderer or plugin processes.
 230     if (sender_) {
 231       queued_logs_.push_back(data);
 232       if (!queue_invoke_later_pending_) {
 233         queue_invoke_later_pending_ = true;
 234         MessageLoop::current()->PostDelayedTask(
 235             FROM_HERE, base::Bind(&Logging::OnSendLogs, base::Unretained(this)),
 236             base::TimeDelta::FromMilliseconds(kLogSendDelayMs));
 237       }
 238     }
 239   }
 240   if (enabled_on_stderr_) {
 241     std::string message_name;
 242     if (data.message_name.empty()) {
 243       message_name = StringPrintf("[unknown type %d]", data.type);
 244     } else {
 245       message_name = data.message_name;
 246     }
 247     double receive_delay =
 248         (Time::FromInternalValue(data.receive) -
 249          Time::FromInternalValue(data.sent)).InSecondsF();
 250     double dispatch_delay =
 251         (Time::FromInternalValue(data.dispatch) -
 252          Time::FromInternalValue(data.sent)).InSecondsF();
 253     fprintf(stderr,
 254             "ipc %s %d %s %s%s %s%s\n  %18.5f %s%18.5f %s%18.5f%s\n",
 255             data.channel.c_str(),
 256             data.routing_id,
 257             data.flags.c_str(),
 258             ANSIEscape(sender_ ? ANSI_COLOR_BLUE : ANSI_COLOR_CYAN),
 259             message_name.c_str(),
 260             ANSIEscape(ANSI_COLOR_RESET),
 261             data.params.c_str(),
 262             Time::FromInternalValue(data.sent).ToDoubleT(),
 263             ANSIEscape(DelayColor(receive_delay)),
 264             Time::FromInternalValue(data.receive).ToDoubleT(),
 265             ANSIEscape(DelayColor(dispatch_delay)),
 266             Time::FromInternalValue(data.dispatch).ToDoubleT(),
 267             ANSIEscape(ANSI_COLOR_RESET)
 268             );
 269   }
 270 }
 271
 272 void GenerateLogData(const std::string& channel, const Message& message,
 273                      LogData* data, bool get_params) {
 274   if (message.is_reply()) {
 275     // "data" should already be filled in.
 276     std::string params;
 277     Logging::GetMessageText(data->type, NULL, &message, &params);
 278
 279     if (!data->params.empty() && !params.empty())
 280       data->params += ", ";
 281
 282     data->flags += " DR";
 283
 284     data->params += params;
 285   } else {
 286     std::string flags;
 287     if (message.is_sync())
 288       flags = "S";
 289
 290     if (message.is_reply())
 291       flags += "R";
 292
 293     if (message.is_reply_error())
 294       flags += "E";
 295
 296     std::string params, message_name;
 297     Logging::GetMessageText(message.type(), &message_name, &message,
 298                             get_params ? &params : NULL);
 299
 300     data->channel = channel;
 301     data->routing_id = message.routing_id();
 302     data->type = message.type();
 303     data->flags = flags;
 304     data->sent = message.sent_time();
 305     data->receive = message.received_time();
 306     data->dispatch = Time::Now().ToInternalValue();
 307     data->params = params;
 308     data->message_name = message_name;
 309   }
 310 }
 311
 312 }
 313
 314 #endif  // IPC_MESSAGE_LOG_ENABLED