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.
5 #include "ipc/ipc_logging.h"
7 #ifdef IPC_MESSAGE_LOG_ENABLED
8 #define IPC_MESSAGE_MACROS_LOG_ENABLED
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/single_thread_task_runner.h"
17 #include "base/strings/string_number_conversions.h"
18 #include "base/strings/string_util.h"
19 #include "base/thread_task_runner_handle.h"
20 #include "base/threading/thread.h"
21 #include "base/time/time.h"
22 #include "ipc/ipc_message_utils.h"
23 #include "ipc/ipc_sender.h"
24 #include "ipc/ipc_switches.h"
25 #include "ipc/ipc_sync_message.h"
31 #ifdef IPC_MESSAGE_LOG_ENABLED
37 const int kLogSendDelayMs
= 100;
39 // We use a pointer to the function table to avoid any linker dependencies on
40 // all the traits used as IPC message parameters.
41 LogFunctionMap
* Logging::log_function_map_
;
45 enabled_on_stderr_(false),
46 enabled_color_(false),
47 queue_invoke_later_pending_(false),
49 main_thread_(base::MessageLoop::current()),
52 // getenv triggers an unsafe warning. Simply check how big of a buffer
53 // would be needed to fetch the value to see if the enviornment variable is
55 size_t requiredSize
= 0;
56 getenv_s(&requiredSize
, NULL
, 0, "CHROME_IPC_LOGGING");
57 bool logging_env_var_set
= (requiredSize
!= 0);
58 if (requiredSize
<= 6) {
60 getenv_s(&requiredSize
, buffer
, sizeof(buffer
), "CHROME_IPC_LOGGING");
61 if (requiredSize
&& !strncmp("color", buffer
, 6))
62 enabled_color_
= true;
64 #else // !defined(OS_WIN)
65 const char* ipc_logging
= getenv("CHROME_IPC_LOGGING");
66 bool logging_env_var_set
= (ipc_logging
!= NULL
);
67 if (ipc_logging
&& !strcmp(ipc_logging
, "color"))
68 enabled_color_
= true;
69 #endif //defined(OS_WIN)
70 if (logging_env_var_set
) {
72 enabled_on_stderr_
= true;
79 Logging
* Logging::GetInstance() {
80 return Singleton
<Logging
>::get();
83 void Logging::SetConsumer(Consumer
* consumer
) {
87 void Logging::Enable() {
91 void Logging::Disable() {
95 void Logging::OnSendLogs() {
96 queue_invoke_later_pending_
= false;
100 Message
* msg
= new Message(
101 MSG_ROUTING_CONTROL
, IPC_LOGGING_ID
, Message::PRIORITY_NORMAL
);
102 WriteParam(msg
, queued_logs_
);
103 queued_logs_
.clear();
107 void Logging::SetIPCSender(IPC::Sender
* sender
) {
111 void Logging::OnReceivedLoggingMessage(const Message
& message
) {
112 std::vector
<LogData
> data
;
113 base::PickleIterator
iter(message
);
114 if (!ReadParam(&message
, &iter
, &data
))
117 for (size_t i
= 0; i
< data
.size(); ++i
) {
122 void Logging::OnSendMessage(Message
* message
, const std::string
& channel_id
) {
126 if (message
->is_reply()) {
127 LogData
* data
= message
->sync_log_data();
131 // This is actually the delayed reply to a sync message. Create a string
132 // of the output parameters, add it to the LogData that was earlier stashed
133 // with the reply, and log the result.
134 GenerateLogData("", *message
, data
, true);
135 data
->channel
= channel_id
;
138 message
->set_sync_log_data(NULL
);
140 // If the time has already been set (i.e. by ChannelProxy), keep that time
141 // instead as it's more accurate.
142 if (!message
->sent_time())
143 message
->set_sent_time(Time::Now().ToInternalValue());
147 void Logging::OnPreDispatchMessage(const Message
& message
) {
148 message
.set_received_time(Time::Now().ToInternalValue());
151 void Logging::OnPostDispatchMessage(const Message
& message
,
152 const std::string
& channel_id
) {
154 !message
.sent_time() ||
155 !message
.received_time() ||
160 GenerateLogData(channel_id
, message
, &data
, true);
162 if (base::MessageLoop::current() == main_thread_
) {
165 main_thread_
->task_runner()->PostTask(
166 FROM_HERE
, base::Bind(&Logging::Log
, base::Unretained(this), data
));
170 void Logging::GetMessageText(uint32_t type
, std::string
* name
,
171 const Message
* message
,
172 std::string
* params
) {
173 if (!log_function_map_
)
176 LogFunctionMap::iterator it
= log_function_map_
->find(type
);
177 if (it
== log_function_map_
->end()) {
179 *name
= "[UNKNOWN MSG ";
180 *name
+= base::IntToString(type
);
186 (*it
->second
)(name
, message
, params
);
189 const char* Logging::ANSIEscape(ANSIColor color
) {
193 case ANSI_COLOR_RESET
:
195 case ANSI_COLOR_BLACK
:
199 case ANSI_COLOR_GREEN
:
201 case ANSI_COLOR_YELLOW
:
203 case ANSI_COLOR_BLUE
:
205 case ANSI_COLOR_MAGENTA
:
207 case ANSI_COLOR_CYAN
:
209 case ANSI_COLOR_WHITE
:
215 Logging::ANSIColor
Logging::DelayColor(double delay
) {
217 return ANSI_COLOR_GREEN
;
219 return ANSI_COLOR_BLACK
;
221 return ANSI_COLOR_YELLOW
;
222 return ANSI_COLOR_RED
;
225 void Logging::Log(const LogData
& data
) {
227 // We're in the browser process.
228 consumer_
->Log(data
);
230 // We're in the renderer or plugin processes.
232 queued_logs_
.push_back(data
);
233 if (!queue_invoke_later_pending_
) {
234 queue_invoke_later_pending_
= true;
235 base::ThreadTaskRunnerHandle::Get()->PostDelayedTask(
236 FROM_HERE
, base::Bind(&Logging::OnSendLogs
, base::Unretained(this)),
237 base::TimeDelta::FromMilliseconds(kLogSendDelayMs
));
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
);
246 message_name
= data
.message_name
;
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();
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(),
259 ANSIEscape(sender_
? ANSI_COLOR_BLUE
: ANSI_COLOR_CYAN
),
260 message_name
.c_str(),
261 ANSIEscape(ANSI_COLOR_RESET
),
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
)
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.
278 Logging::GetMessageText(data
->type
, NULL
, &message
, ¶ms
);
280 if (!data
->params
.empty() && !params
.empty())
281 data
->params
+= ", ";
283 data
->flags
+= " DR";
285 data
->params
+= params
;
288 if (message
.is_sync())
291 if (message
.is_reply())
294 if (message
.is_reply_error())
297 std::string params
, message_name
;
298 Logging::GetMessageText(message
.type(), &message_name
, &message
,
299 get_params
? ¶ms
: NULL
);
301 data
->channel
= channel
;
302 data
->routing_id
= message
.routing_id();
303 data
->type
= message
.type();
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
;
315 #endif // IPC_MESSAGE_LOG_ENABLED