ipc/ipc_logging.cc

   1 // Copyright (c) 2006-2008 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 // This will cause render_messages.h etc to define ViewMsgLog and friends.
   9 #define IPC_MESSAGE_MACROS_LOG_ENABLED
  10 #endif
  11
  12 #include "base/command_line.h"
  13 #include "base/logging.h"
  14 #include "base/message_loop.h"
  15 #include "base/process_util.h"
  16 #include "base/string_util.h"
  17 #include "base/thread.h"
  18 #include "base/time.h"
  19 #include "base/waitable_event.h"
  20 #include "base/waitable_event_watcher.h"
  21 #include "ipc/ipc_switches.h"
  22 #include "ipc/ipc_sync_message.h"
  23 #include "ipc/ipc_message_utils.h"
  24
  25 #if defined(OS_POSIX)
  26 #include <unistd.h>
  27 #endif
  28
  29 #ifdef IPC_MESSAGE_LOG_ENABLED
  30
  31 using base::Time;
  32
  33 // IPC::Logging is allocated as a singleton, so we don't need any kind of
  34 // special retention program.
  35 template <>
  36 struct RunnableMethodTraits<IPC::Logging> {
  37   void RetainCallee(IPC::Logging*) {}
  38   void ReleaseCallee(IPC::Logging*) {}
  39 };
  40
  41 namespace IPC {
  42
  43 const int kLogSendDelayMs = 100;
  44
  45 // We use a pointer to the function table to avoid any linker dependencies on
  46 // all the traits used as IPC message parameters.
  47 Logging::LogFunction *Logging::log_function_mapping_;
  48
  49 Logging::Logging()
  50     : enabled_(false),
  51       enabled_on_stderr_(false),
  52       queue_invoke_later_pending_(false),
  53       sender_(NULL),
  54       main_thread_(MessageLoop::current()),
  55       consumer_(NULL) {
  56   if (getenv("CHROME_IPC_LOGGING")) {
  57     enabled_ = true;
  58     enabled_on_stderr_ = true;
  59   }
  60 }
  61
  62 Logging::~Logging() {
  63 }
  64
  65 Logging* Logging::current() {
  66   return Singleton<Logging>::get();
  67 }
  68
  69 void Logging::SetLoggerFunctions(LogFunction *functions) {
  70   log_function_mapping_ = functions;
  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::wstring* name,
 161                              const Message* message,
 162                              std::wstring* params) {
 163   if (!log_function_mapping_)
 164     return;
 165
 166   int message_class = type >> 16;
 167   if (log_function_mapping_[message_class] != NULL) {
 168     log_function_mapping_[message_class](type, name, message, params);
 169   } else {
 170     DLOG(INFO) << "No logger function associated with message class " <<
 171         message_class;
 172   }
 173 }
 174
 175 void Logging::Log(const LogData& data) {
 176   if (consumer_) {
 177     // We're in the browser process.
 178     consumer_->Log(data);
 179   } else {
 180     // We're in the renderer or plugin processes.
 181     if (sender_) {
 182       queued_logs_.push_back(data);
 183       if (!queue_invoke_later_pending_) {
 184         queue_invoke_later_pending_ = true;
 185         MessageLoop::current()->PostDelayedTask(FROM_HERE, NewRunnableMethod(
 186             this, &Logging::OnSendLogs), kLogSendDelayMs);
 187       }
 188     }
 189   }
 190   if (enabled_on_stderr_) {
 191     std::string message_name;
 192     if (data.message_name.empty()) {
 193       message_name = StringPrintf("[unknown type %d]", data.type);
 194     } else {
 195       message_name = WideToASCII(data.message_name);
 196     }
 197     fprintf(stderr, "ipc %s %d %s %s %s\n",
 198             data.channel.c_str(),
 199             data.routing_id,
 200             WideToASCII(data.flags).c_str(),
 201             message_name.c_str(),
 202             WideToUTF8(data.params).c_str());
 203   }
 204 }
 205
 206 void GenerateLogData(const std::string& channel, const Message& message,
 207                      LogData* data) {
 208   if (message.is_reply()) {
 209     // "data" should already be filled in.
 210     std::wstring params;
 211     Logging::GetMessageText(data->type, NULL, &message, &params);
 212
 213     if (!data->params.empty() && !params.empty())
 214       data->params += L", ";
 215
 216     data->flags += L" DR";
 217
 218     data->params += params;
 219   } else {
 220     std::wstring flags;
 221     if (message.is_sync())
 222       flags = L"S";
 223
 224     if (message.is_reply())
 225       flags += L"R";
 226
 227     if (message.is_reply_error())
 228       flags += L"E";
 229
 230     std::wstring params, message_name;
 231     Logging::GetMessageText(message.type(), &message_name, &message, &params);
 232
 233     data->channel = channel;
 234     data->routing_id = message.routing_id();
 235     data->type = message.type();
 236     data->flags = flags;
 237     data->sent = message.sent_time();
 238     data->receive = message.received_time();
 239     data->dispatch = Time::Now().ToInternalValue();
 240     data->params = params;
 241     data->message_name = message_name;
 242   }
 243 }
 244
 245 }
 246
 247 #endif  // IPC_MESSAGE_LOG_ENABLED