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