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
32using base::Time;
33
34namespace IPC {
35
36const 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.
40LogFunctionMap* Logging::log_function_map_;
41
42Logging::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
75Logging::~Logging() {
76}
77
78Logging* Logging::GetInstance() {
79  return Singleton<Logging>::get();
80}
81
82void Logging::SetConsumer(Consumer* consumer) {
83  consumer_ = consumer;
84}
85
86void Logging::Enable() {
87  enabled_ = true;
88}
89
90void Logging::Disable() {
91  enabled_ = false;
92}
93
94void 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
106void Logging::SetIPCSender(IPC::Sender* sender) {
107  sender_ = sender;
108}
109
110void 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
121void 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
146void Logging::OnPreDispatchMessage(const Message& message) {
147  message.set_received_time(Time::Now().ToInternalValue());
148}
149
150void 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
169void 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
188const 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
214Logging::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
224void 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
273void 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, &params);
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 ? &params : 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