Home | History | Annotate | Download | only in ipc 
      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/message_loop.h"
     17 #include "base/strings/string_number_conversions.h"
     18 #include "base/strings/string_util.h"
     19 #include "base/threading/thread.h"
     20 #include "base/time/time.h"
     21 #include "ipc/ipc_message_utils.h"
     22 #include "ipc/ipc_sender.h"
     23 #include "ipc/ipc_switches.h"
     24 #include "ipc/ipc_sync_message.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_(base::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::Sender* sender) {
    107   sender_ = sender;
    108 }
    109 
    110 void Logging::OnReceivedLoggingMessage(const Message& message) {
    111   std::vector<LogData> data;
    112   PickleIterator iter(message);
    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     GenerateLogData("", *message, data, true);
    134     data->channel = channel_id;
    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 (base::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         base::MessageLoop::current()->PostDelayedTask(
    235             FROM_HERE,
    236             base::Bind(&Logging::OnSendLogs, base::Unretained(this)),
    237             base::TimeDelta::FromMilliseconds(kLogSendDelayMs));
    238       }
    239     }
    240   }
    241   if (enabled_on_stderr_) {
    242     std::string message_name;
    243     if (data.message_name.empty()) {
    244       message_name = base::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
    316