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