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