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