ipc/chromium/src/chrome/common/ipc_logging.cc

Wed, 31 Dec 2014 13:27:57 +0100

author
Michael Schloh von Bennewitz <michael@schloh.com>
date
Wed, 31 Dec 2014 13:27:57 +0100
branch
TOR_BUG_3246
changeset 6
8bccb770b82d
permissions
-rw-r--r--

Ignore runtime configuration files generated during quality assurance.

michael@0 1 // Copyright (c) 2006-2008 The Chromium Authors. All rights reserved.
michael@0 2 // Use of this source code is governed by a BSD-style license that can be
michael@0 3 // found in the LICENSE file.
michael@0 4
michael@0 5 #include "chrome/common/ipc_logging.h"
michael@0 6
michael@0 7 #if defined(OS_POSIX)
michael@0 8 #ifdef IPC_MESSAGE_LOG_ENABLED
michael@0 9 // This will cause render_messages.h etc to define ViewMsgLog and friends.
michael@0 10 #define IPC_MESSAGE_MACROS_LOG_ENABLED
michael@0 11 #endif
michael@0 12 #endif
michael@0 13
michael@0 14 #include "base/command_line.h"
michael@0 15 #include "base/logging.h"
michael@0 16 #include "base/message_loop.h"
michael@0 17 #include "base/string_util.h"
michael@0 18 #include "base/thread.h"
michael@0 19 #include "base/time.h"
michael@0 20 #include "base/waitable_event.h"
michael@0 21 #include "base/waitable_event_watcher.h"
michael@0 22 #include "chrome/common/chrome_switches.h"
michael@0 23 #include "chrome/common/ipc_sync_message.h"
michael@0 24 #include "chrome/common/ipc_message_utils.h"
michael@0 25
michael@0 26 #if defined(OS_POSIX)
michael@0 27 #include "base/string_util.h"
michael@0 28 #include <unistd.h>
michael@0 29 #endif
michael@0 30
michael@0 31 #ifdef IPC_MESSAGE_LOG_ENABLED
michael@0 32
michael@0 33 using base::Time;
michael@0 34
michael@0 35 // IPC::Logging is allocated as a singleton, so we don't need any kind of
michael@0 36 // special retention program.
michael@0 37 template <>
michael@0 38 struct RunnableMethodTraits<IPC::Logging> {
michael@0 39 static void RetainCallee(IPC::Logging*) {}
michael@0 40 static void ReleaseCallee(IPC::Logging*) {}
michael@0 41 };
michael@0 42
michael@0 43 namespace IPC {
michael@0 44
michael@0 45 const wchar_t kLoggingEventName[] = L"ChromeIPCLog.%d";
michael@0 46 const int kLogSendDelayMs = 100;
michael@0 47
michael@0 48 // We use a pointer to the function table to avoid any linker dependencies on
michael@0 49 // all the traits used as IPC message parameters.
michael@0 50 Logging::LogFunction *Logging::log_function_mapping_;
michael@0 51
michael@0 52 Logging::Logging()
michael@0 53 : logging_event_on_(NULL),
michael@0 54 logging_event_off_(NULL),
michael@0 55 enabled_(false),
michael@0 56 queue_invoke_later_pending_(false),
michael@0 57 sender_(NULL),
michael@0 58 main_thread_(MessageLoop::current()),
michael@0 59 consumer_(NULL) {
michael@0 60 // Create an event for this browser instance that's set when logging is
michael@0 61 // enabled, so child processes can know when logging is enabled.
michael@0 62
michael@0 63 #if defined(OS_WIN)
michael@0 64 // On Windows we have a couple of named events which switch logging on and
michael@0 65 // off.
michael@0 66 int browser_pid;
michael@0 67 const CommandLine& parsed_command_line = *CommandLine::ForCurrentProcess();
michael@0 68 std::wstring process_type =
michael@0 69 parsed_command_line.GetSwitchValue(switches::kProcessType);
michael@0 70 if (process_type.empty()) {
michael@0 71 browser_pid = GetCurrentProcessId();
michael@0 72 } else {
michael@0 73 std::wstring channel_name =
michael@0 74 parsed_command_line.GetSwitchValue(switches::kProcessChannelID);
michael@0 75
michael@0 76 browser_pid = _wtoi(channel_name.c_str());
michael@0 77 DCHECK(browser_pid != 0);
michael@0 78 }
michael@0 79
michael@0 80 std::wstring event_name = GetEventName(browser_pid, true);
michael@0 81 logging_event_on_.reset(new base::WaitableEvent(
michael@0 82 CreateEventW(NULL, TRUE, FALSE, event_name.c_str())));
michael@0 83
michael@0 84 event_name = GetEventName(browser_pid, false);
michael@0 85 logging_event_off_.reset(new base::WaitableEvent(
michael@0 86 CreateEventW(NULL, TRUE, FALSE, event_name.c_str())));
michael@0 87
michael@0 88 RegisterWaitForEvent(true);
michael@0 89 #endif
michael@0 90
michael@0 91 MessageLoop::current()->AddDestructionObserver(this);
michael@0 92 }
michael@0 93
michael@0 94 Logging::~Logging() {
michael@0 95 }
michael@0 96
michael@0 97 Logging* Logging::current() {
michael@0 98 return Singleton<Logging>::get();
michael@0 99 }
michael@0 100
michael@0 101 void Logging::RegisterWaitForEvent(bool enabled) {
michael@0 102 watcher_.StopWatching();
michael@0 103 watcher_.StartWatching(
michael@0 104 enabled ? logging_event_on_.get() : logging_event_off_.get(), this);
michael@0 105 }
michael@0 106
michael@0 107 void Logging::OnWaitableEventSignaled(base::WaitableEvent* event) {
michael@0 108 enabled_ = event == logging_event_on_.get();
michael@0 109 RegisterWaitForEvent(!enabled_);
michael@0 110 }
michael@0 111
michael@0 112 void Logging::WillDestroyCurrentMessageLoop() {
michael@0 113 watcher_.StopWatching();
michael@0 114 }
michael@0 115
michael@0 116 void Logging::SetLoggerFunctions(LogFunction *functions) {
michael@0 117 log_function_mapping_ = functions;
michael@0 118 }
michael@0 119
michael@0 120 #if defined(OS_WIN)
michael@0 121 std::wstring Logging::GetEventName(bool enabled) {
michael@0 122 return current()->GetEventName(GetCurrentProcessId(), enabled);
michael@0 123 }
michael@0 124 #endif
michael@0 125
michael@0 126 std::wstring Logging::GetEventName(int browser_pid, bool enabled) {
michael@0 127 std::wstring result = StringPrintf(kLoggingEventName, browser_pid);
michael@0 128 result += enabled ? L"on" : L"off";
michael@0 129 return result;
michael@0 130 }
michael@0 131
michael@0 132 void Logging::SetConsumer(Consumer* consumer) {
michael@0 133 consumer_ = consumer;
michael@0 134 }
michael@0 135
michael@0 136 void Logging::Enable() {
michael@0 137 logging_event_off_->Reset();
michael@0 138 logging_event_on_->Signal();
michael@0 139 }
michael@0 140
michael@0 141 void Logging::Disable() {
michael@0 142 logging_event_on_->Reset();
michael@0 143 logging_event_off_->Signal();
michael@0 144 }
michael@0 145
michael@0 146 void Logging::OnSendLogs() {
michael@0 147 queue_invoke_later_pending_ = false;
michael@0 148 if (!sender_)
michael@0 149 return;
michael@0 150
michael@0 151 Message* msg = new Message(
michael@0 152 MSG_ROUTING_CONTROL, IPC_LOGGING_ID, Message::PRIORITY_NORMAL);
michael@0 153 WriteParam(msg, queued_logs_);
michael@0 154 queued_logs_.clear();
michael@0 155 sender_->Send(msg);
michael@0 156 }
michael@0 157
michael@0 158 void Logging::SetIPCSender(IPC::Message::Sender* sender) {
michael@0 159 sender_ = sender;
michael@0 160 }
michael@0 161
michael@0 162 void Logging::OnReceivedLoggingMessage(const Message& message) {
michael@0 163 std::vector<LogData> data;
michael@0 164 void* iter = NULL;
michael@0 165 if (!ReadParam(&message, &iter, &data))
michael@0 166 return;
michael@0 167
michael@0 168 for (size_t i = 0; i < data.size(); ++i) {
michael@0 169 Log(data[i]);
michael@0 170 }
michael@0 171 }
michael@0 172
michael@0 173 void Logging::OnSendMessage(Message* message, const std::wstring& channel_id) {
michael@0 174 if (!Enabled())
michael@0 175 return;
michael@0 176
michael@0 177 if (message->is_reply()) {
michael@0 178 LogData* data = message->sync_log_data();
michael@0 179 if (!data)
michael@0 180 return;
michael@0 181
michael@0 182 // This is actually the delayed reply to a sync message. Create a string
michael@0 183 // of the output parameters, add it to the LogData that was earlier stashed
michael@0 184 // with the reply, and log the result.
michael@0 185 data->channel = channel_id;
michael@0 186 GenerateLogData(L"", *message, data);
michael@0 187 Log(*data);
michael@0 188 delete data;
michael@0 189 message->set_sync_log_data(NULL);
michael@0 190 } else {
michael@0 191 // If the time has already been set (i.e. by ChannelProxy), keep that time
michael@0 192 // instead as it's more accurate.
michael@0 193 if (!message->sent_time())
michael@0 194 message->set_sent_time(Time::Now().ToInternalValue());
michael@0 195 }
michael@0 196 }
michael@0 197
michael@0 198 void Logging::OnPreDispatchMessage(const Message& message) {
michael@0 199 message.set_received_time(Time::Now().ToInternalValue());
michael@0 200 }
michael@0 201
michael@0 202 void Logging::OnPostDispatchMessage(const Message& message,
michael@0 203 const std::wstring& channel_id) {
michael@0 204 if (!Enabled() ||
michael@0 205 #if defined(OS_WIN)
michael@0 206 !message.sent_time() ||
michael@0 207 #endif
michael@0 208 message.dont_log())
michael@0 209 return;
michael@0 210
michael@0 211 LogData data;
michael@0 212 GenerateLogData(channel_id, message, &data);
michael@0 213
michael@0 214 if (MessageLoop::current() == main_thread_) {
michael@0 215 Log(data);
michael@0 216 } else {
michael@0 217 main_thread_->PostTask(FROM_HERE, NewRunnableMethod(
michael@0 218 this, &Logging::Log, data));
michael@0 219 }
michael@0 220 }
michael@0 221
michael@0 222 void Logging::GetMessageText(uint16_t type, std::wstring* name,
michael@0 223 const Message* message,
michael@0 224 std::wstring* params) {
michael@0 225 if (!log_function_mapping_)
michael@0 226 return;
michael@0 227
michael@0 228 int message_class = type >> 12;
michael@0 229 if (log_function_mapping_[message_class] != NULL) {
michael@0 230 log_function_mapping_[message_class](type, name, message, params);
michael@0 231 } else {
michael@0 232 DLOG(INFO) << "No logger function associated with message class " <<
michael@0 233 message_class;
michael@0 234 }
michael@0 235 }
michael@0 236
michael@0 237 void Logging::Log(const LogData& data) {
michael@0 238 #if defined(OS_WIN)
michael@0 239 if (consumer_) {
michael@0 240 // We're in the browser process.
michael@0 241 consumer_->Log(data);
michael@0 242 } else {
michael@0 243 // We're in the renderer or plugin processes.
michael@0 244 if (sender_) {
michael@0 245 queued_logs_.push_back(data);
michael@0 246 if (!queue_invoke_later_pending_) {
michael@0 247 queue_invoke_later_pending_ = true;
michael@0 248 MessageLoop::current()->PostDelayedTask(FROM_HERE, NewRunnableMethod(
michael@0 249 this, &Logging::OnSendLogs), kLogSendDelayMs);
michael@0 250 }
michael@0 251 }
michael@0 252 }
michael@0 253 #elif defined(OS_POSIX)
michael@0 254 // On POSIX, for now, we just dump the log to stderr
michael@0 255 fprintf(stderr, "ipc %s %d %d %s %s %s\n",
michael@0 256 WideToUTF8(data.channel).c_str(),
michael@0 257 data.routing_id,
michael@0 258 data.type,
michael@0 259 WideToUTF8(data.flags).c_str(),
michael@0 260 WideToUTF8(data.message_name).c_str(),
michael@0 261 WideToUTF8(data.params).c_str());
michael@0 262 #endif
michael@0 263 }
michael@0 264
michael@0 265 void GenerateLogData(const std::wstring& channel, const Message& message,
michael@0 266 LogData* data) {
michael@0 267 if (message.is_reply()) {
michael@0 268 // "data" should already be filled in.
michael@0 269 std::wstring params;
michael@0 270 Logging::GetMessageText(data->type, NULL, &message, &params);
michael@0 271
michael@0 272 if (!data->params.empty() && !params.empty())
michael@0 273 data->params += L", ";
michael@0 274
michael@0 275 data->flags += L" DR";
michael@0 276
michael@0 277 data->params += params;
michael@0 278 } else {
michael@0 279 std::wstring flags;
michael@0 280 if (message.is_sync())
michael@0 281 flags = L"S";
michael@0 282
michael@0 283 if (message.is_reply())
michael@0 284 flags += L"R";
michael@0 285
michael@0 286 if (message.is_reply_error())
michael@0 287 flags += L"E";
michael@0 288
michael@0 289 std::wstring params, message_name;
michael@0 290 Logging::GetMessageText(message.type(), &message_name, &message, &params);
michael@0 291
michael@0 292 data->channel = channel;
michael@0 293 data->routing_id = message.routing_id();
michael@0 294 data->type = message.type();
michael@0 295 data->flags = flags;
michael@0 296 data->sent = message.sent_time();
michael@0 297 data->receive = message.received_time();
michael@0 298 data->dispatch = Time::Now().ToInternalValue();
michael@0 299 data->params = params;
michael@0 300 data->message_name = message_name;
michael@0 301 }
michael@0 302 }
michael@0 303
michael@0 304 }
michael@0 305
michael@0 306 #endif // IPC_MESSAGE_LOG_ENABLED

mercurial