ipc/ipc_logging.cc

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