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/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"
30 #ifdef IPC_MESSAGE_LOG_ENABLED
36 const int kLogSendDelayMs
= 100;
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_
;
44 enabled_on_stderr_(false),
45 enabled_color_(false),
46 queue_invoke_later_pending_(false),
48 main_thread_(base::MessageLoop::current()),
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
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) {
59 getenv_s(&requiredSize
, buffer
, sizeof(buffer
), "CHROME_IPC_LOGGING");
60 if (requiredSize
&& !strncmp("color", buffer
, 6))
61 enabled_color_
= true;
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
) {
71 enabled_on_stderr_
= true;
78 Logging
* Logging::GetInstance() {
79 return Singleton
<Logging
>::get();
82 void Logging::SetConsumer(Consumer
* consumer
) {
86 void Logging::Enable() {
90 void Logging::Disable() {
94 void Logging::OnSendLogs() {
95 queue_invoke_later_pending_
= false;
99 Message
* msg
= new Message(
100 MSG_ROUTING_CONTROL
, IPC_LOGGING_ID
, Message::PRIORITY_NORMAL
);
101 WriteParam(msg
, queued_logs_
);
102 queued_logs_
.clear();
106 void Logging::SetIPCSender(IPC::Sender
* sender
) {
110 void Logging::OnReceivedLoggingMessage(const Message
& message
) {
111 std::vector
<LogData
> data
;
112 PickleIterator
iter(message
);
113 if (!ReadParam(&message
, &iter
, &data
))
116 for (size_t i
= 0; i
< data
.size(); ++i
) {
121 void Logging::OnSendMessage(Message
* message
, const std::string
& channel_id
) {
125 if (message
->is_reply()) {
126 LogData
* data
= message
->sync_log_data();
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
;
137 message
->set_sync_log_data(NULL
);
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());
146 void Logging::OnPreDispatchMessage(const Message
& message
) {
147 message
.set_received_time(Time::Now().ToInternalValue());
150 void Logging::OnPostDispatchMessage(const Message
& message
,
151 const std::string
& channel_id
) {
153 !message
.sent_time() ||
154 !message
.received_time() ||
159 GenerateLogData(channel_id
, message
, &data
, true);
161 if (base::MessageLoop::current() == main_thread_
) {
164 main_thread_
->PostTask(
165 FROM_HERE
, base::Bind(&Logging::Log
, base::Unretained(this), data
));
169 void Logging::GetMessageText(uint32 type
, std::string
* name
,
170 const Message
* message
,
171 std::string
* params
) {
172 if (!log_function_map_
)
175 LogFunctionMap::iterator it
= log_function_map_
->find(type
);
176 if (it
== log_function_map_
->end()) {
178 *name
= "[UNKNOWN MSG ";
179 *name
+= base::IntToString(type
);
185 (*it
->second
)(name
, message
, params
);
188 const char* Logging::ANSIEscape(ANSIColor color
) {
192 case ANSI_COLOR_RESET
:
194 case ANSI_COLOR_BLACK
:
198 case ANSI_COLOR_GREEN
:
200 case ANSI_COLOR_YELLOW
:
202 case ANSI_COLOR_BLUE
:
204 case ANSI_COLOR_MAGENTA
:
206 case ANSI_COLOR_CYAN
:
208 case ANSI_COLOR_WHITE
:
214 Logging::ANSIColor
Logging::DelayColor(double delay
) {
216 return ANSI_COLOR_GREEN
;
218 return ANSI_COLOR_BLACK
;
220 return ANSI_COLOR_YELLOW
;
221 return ANSI_COLOR_RED
;
224 void Logging::Log(const LogData
& data
) {
226 // We're in the browser process.
227 consumer_
->Log(data
);
229 // We're in the renderer or plugin processes.
231 queued_logs_
.push_back(data
);
232 if (!queue_invoke_later_pending_
) {
233 queue_invoke_later_pending_
= true;
234 base::MessageLoop::current()->PostDelayedTask(
236 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