ipc_logging.cc 8.4 KB

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