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 #if BUILDFLAG(IPC_MESSAGE_LOG_ENABLED)
8 #define IPC_MESSAGE_MACROS_LOG_ENABLED
9 #endif
10
11 #include <stddef.h>
12 #include <stdint.h>
13
14 #include "base/bind.h"
15 #include "base/bind_helpers.h"
16 #include "base/command_line.h"
17 #include "base/location.h"
18 #include "base/logging.h"
19 #include "base/strings/string_number_conversions.h"
20 #include "base/strings/string_util.h"
21 #include "base/threading/thread.h"
22 #include "base/threading/thread_task_runner_handle.h"
23 #include "base/threading/thread_task_runner_handle.h"
24 #include "base/time/time.h"
25 #include "build/build_config.h"
26 #include "ipc/ipc_message_utils.h"
27 #include "ipc/ipc_sender.h"
28 #include "ipc/ipc_sync_message.h"
29
30 #if defined(OS_POSIX)
31 #include <unistd.h>
32 #endif
33
34 #if BUILDFLAG(IPC_MESSAGE_LOG_ENABLED)
35
36 using base::Time;
37
38 namespace IPC {
39
40 const int kLogSendDelayMs = 100;
41
42 // We use a pointer to the function table to avoid any linker dependencies on
43 // all the traits used as IPC message parameters.
44 LogFunctionMap* Logging::log_function_map_;
45
Logging()46 Logging::Logging()
47 : enabled_(false),
48 enabled_on_stderr_(false),
49 enabled_color_(false),
50 queue_invoke_later_pending_(false),
51 sender_(NULL),
52 main_thread_(base::ThreadTaskRunnerHandle::Get()),
53 consumer_(NULL) {
54 #if defined(OS_WIN)
55 // getenv triggers an unsafe warning. Simply check how big of a buffer
56 // would be needed to fetch the value to see if the enviornment variable is
57 // set.
58 size_t requiredSize = 0;
59 getenv_s(&requiredSize, NULL, 0, "CHROME_IPC_LOGGING");
60 bool logging_env_var_set = (requiredSize != 0);
61 if (requiredSize <= 6) {
62 char buffer[6];
63 getenv_s(&requiredSize, buffer, sizeof(buffer), "CHROME_IPC_LOGGING");
64 if (requiredSize && !strncmp("color", buffer, 6))
65 enabled_color_ = true;
66 }
67 #else // !defined(OS_WIN)
68 const char* ipc_logging = getenv("CHROME_IPC_LOGGING");
69 bool logging_env_var_set = (ipc_logging != NULL);
70 if (ipc_logging && !strcmp(ipc_logging, "color"))
71 enabled_color_ = true;
72 #endif //defined(OS_WIN)
73 if (logging_env_var_set) {
74 enabled_ = true;
75 enabled_on_stderr_ = true;
76 }
77 }
78
~Logging()79 Logging::~Logging() {
80 }
81
GetInstance()82 Logging* Logging::GetInstance() {
83 return base::Singleton<Logging>::get();
84 }
85
SetConsumer(Consumer * consumer)86 void Logging::SetConsumer(Consumer* consumer) {
87 consumer_ = consumer;
88 }
89
Enable()90 void Logging::Enable() {
91 enabled_ = true;
92 }
93
Disable()94 void Logging::Disable() {
95 enabled_ = false;
96 }
97
OnSendLogs()98 void Logging::OnSendLogs() {
99 queue_invoke_later_pending_ = false;
100 if (!sender_)
101 return;
102
103 Message* msg = new Message(
104 MSG_ROUTING_CONTROL, IPC_LOGGING_ID, Message::PRIORITY_NORMAL);
105 WriteParam(msg, queued_logs_);
106 queued_logs_.clear();
107 sender_->Send(msg);
108 }
109
SetIPCSender(IPC::Sender * sender)110 void Logging::SetIPCSender(IPC::Sender* sender) {
111 sender_ = sender;
112 }
113
OnReceivedLoggingMessage(const Message & message)114 void Logging::OnReceivedLoggingMessage(const Message& message) {
115 std::vector<LogData> data;
116 base::PickleIterator iter(message);
117 if (!ReadParam(&message, &iter, &data))
118 return;
119
120 for (size_t i = 0; i < data.size(); ++i) {
121 Log(data[i]);
122 }
123 }
124
OnSendMessage(Message * message)125 void Logging::OnSendMessage(Message* message) {
126 if (!Enabled())
127 return;
128
129 if (message->is_reply()) {
130 LogData* data = message->sync_log_data();
131 if (!data)
132 return;
133
134 // This is actually the delayed reply to a sync message. Create a string
135 // of the output parameters, add it to the LogData that was earlier stashed
136 // with the reply, and log the result.
137 GenerateLogData(*message, data, true);
138 Log(*data);
139 delete data;
140 message->set_sync_log_data(NULL);
141 } else {
142 // If the time has already been set (i.e. by ChannelProxy), keep that time
143 // instead as it's more accurate.
144 if (!message->sent_time())
145 message->set_sent_time(Time::Now().ToInternalValue());
146 }
147 }
148
OnPreDispatchMessage(const Message & message)149 void Logging::OnPreDispatchMessage(const Message& message) {
150 message.set_received_time(Time::Now().ToInternalValue());
151 }
152
OnPostDispatchMessage(const Message & message)153 void Logging::OnPostDispatchMessage(const Message& message) {
154 if (!Enabled() ||
155 !message.sent_time() ||
156 !message.received_time() ||
157 message.dont_log())
158 return;
159
160 LogData data;
161 GenerateLogData(message, &data, true);
162
163 if (main_thread_->BelongsToCurrentThread()) {
164 Log(data);
165 } else {
166 main_thread_->PostTask(
167 FROM_HERE, base::Bind(&Logging::Log, base::Unretained(this), data));
168 }
169 }
170
GetMessageText(uint32_t type,std::string * name,const Message * message,std::string * params)171 void Logging::GetMessageText(uint32_t type, std::string* name,
172 const Message* message,
173 std::string* params) {
174 if (!log_function_map_)
175 return;
176
177 LogFunctionMap::iterator it = log_function_map_->find(type);
178 if (it == log_function_map_->end()) {
179 if (name) {
180 *name = "[UNKNOWN MSG ";
181 *name += base::IntToString(type);
182 *name += " ]";
183 }
184 return;
185 }
186
187 (*it->second)(name, message, params);
188 }
189
ANSIEscape(ANSIColor color)190 const char* Logging::ANSIEscape(ANSIColor color) {
191 if (!enabled_color_)
192 return "";
193 switch (color) {
194 case ANSI_COLOR_RESET:
195 return "\033[m";
196 case ANSI_COLOR_BLACK:
197 return "\033[0;30m";
198 case ANSI_COLOR_RED:
199 return "\033[0;31m";
200 case ANSI_COLOR_GREEN:
201 return "\033[0;32m";
202 case ANSI_COLOR_YELLOW:
203 return "\033[0;33m";
204 case ANSI_COLOR_BLUE:
205 return "\033[0;34m";
206 case ANSI_COLOR_MAGENTA:
207 return "\033[0;35m";
208 case ANSI_COLOR_CYAN:
209 return "\033[0;36m";
210 case ANSI_COLOR_WHITE:
211 return "\033[0;37m";
212 }
213 return "";
214 }
215
DelayColor(double delay)216 Logging::ANSIColor Logging::DelayColor(double delay) {
217 if (delay < 0.1)
218 return ANSI_COLOR_GREEN;
219 if (delay < 0.25)
220 return ANSI_COLOR_BLACK;
221 if (delay < 0.5)
222 return ANSI_COLOR_YELLOW;
223 return ANSI_COLOR_RED;
224 }
225
Log(const LogData & data)226 void Logging::Log(const LogData& data) {
227 if (consumer_) {
228 // We're in the browser process.
229 consumer_->Log(data);
230 } else {
231 // We're in the renderer or plugin processes.
232 if (sender_) {
233 queued_logs_.push_back(data);
234 if (!queue_invoke_later_pending_) {
235 queue_invoke_later_pending_ = true;
236 base::ThreadTaskRunnerHandle::Get()->PostDelayedTask(
237 FROM_HERE, base::Bind(&Logging::OnSendLogs, base::Unretained(this)),
238 base::TimeDelta::FromMilliseconds(kLogSendDelayMs));
239 }
240 }
241 }
242 if (enabled_on_stderr_) {
243 std::string message_name;
244 if (data.message_name.empty()) {
245 message_name = base::StringPrintf("[unknown type %d]", data.type);
246 } else {
247 message_name = data.message_name;
248 }
249 double receive_delay =
250 (Time::FromInternalValue(data.receive) -
251 Time::FromInternalValue(data.sent)).InSecondsF();
252 double dispatch_delay =
253 (Time::FromInternalValue(data.dispatch) -
254 Time::FromInternalValue(data.sent)).InSecondsF();
255 fprintf(stderr,
256 "ipc %d %s %s%s %s%s\n %18.5f %s%18.5f %s%18.5f%s\n",
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
GenerateLogData(const Message & message,LogData * data,bool get_params)273 void GenerateLogData(const Message& message, LogData* data, bool get_params) {
274 if (message.is_reply()) {
275 // "data" should already be filled in.
276 std::string params;
277 Logging::GetMessageText(data->type, NULL, &message, ¶ms);
278
279 if (!data->params.empty() && !params.empty())
280 data->params += ", ";
281
282 data->flags += " DR";
283
284 data->params += params;
285 } else {
286 std::string flags;
287 if (message.is_sync())
288 flags = "S";
289
290 if (message.is_reply())
291 flags += "R";
292
293 if (message.is_reply_error())
294 flags += "E";
295
296 std::string params, message_name;
297 Logging::GetMessageText(message.type(), &message_name, &message,
298 get_params ? ¶ms : NULL);
299
300 data->routing_id = message.routing_id();
301 data->type = message.type();
302 data->flags = flags;
303 data->sent = message.sent_time();
304 data->receive = message.received_time();
305 data->dispatch = Time::Now().ToInternalValue();
306 data->params = params;
307 data->message_name = message_name;
308 }
309 }
310
311 }
312
313 #endif // BUILDFLAG(IPC_MESSAGE_LOG_ENABLED)
314