Wed, 31 Dec 2014 06:09:35 +0100
Cloned upstream origin tor-browser at tor-browser-31.3.0esr-4.5-1-build1
revision ID fc1c9ff7c1b2defdbc039f12214767608f46423f for hacking purpose.
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, ¶ms); |
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, ¶ms); |
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 |