123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316 |
- // Copyright (c) 2012 The Chromium Authors. All rights reserved.
- // Use of this source code is governed by a BSD-style license that can be
- // found in the LICENSE file.
- #include "ipc/ipc_logging.h"
- #include "build/build_config.h"
- #if BUILDFLAG(IPC_MESSAGE_LOG_ENABLED)
- #define IPC_MESSAGE_MACROS_LOG_ENABLED
- #endif
- #include <stddef.h>
- #include <stdint.h>
- #include "base/bind.h"
- #include "base/callback_helpers.h"
- #include "base/command_line.h"
- #include "base/location.h"
- #include "base/logging.h"
- #include "base/strings/string_number_conversions.h"
- #include "base/strings/string_util.h"
- #include "base/strings/stringprintf.h"
- #include "base/threading/thread.h"
- #include "base/threading/thread_task_runner_handle.h"
- #include "base/time/time.h"
- #include "build/build_config.h"
- #include "ipc/ipc_message_utils.h"
- #include "ipc/ipc_sender.h"
- #include "ipc/ipc_sync_message.h"
- #if BUILDFLAG(IS_POSIX)
- #include <unistd.h>
- #endif
- #if BUILDFLAG(IPC_MESSAGE_LOG_ENABLED)
- using base::Time;
- namespace IPC {
- const int kLogSendDelayMs = 100;
- // We use a pointer to the function table to avoid any linker dependencies on
- // all the traits used as IPC message parameters.
- LogFunctionMap* Logging::log_function_map_;
- Logging::Logging()
- : enabled_(false),
- enabled_on_stderr_(false),
- enabled_color_(false),
- queue_invoke_later_pending_(false),
- sender_(nullptr),
- main_thread_(base::ThreadTaskRunnerHandle::Get()),
- consumer_(nullptr) {
- #if BUILDFLAG(IS_WIN)
- // getenv triggers an unsafe warning. Simply check how big of a buffer
- // would be needed to fetch the value to see if the enviornment variable is
- // set.
- size_t requiredSize = 0;
- getenv_s(&requiredSize, NULL, 0, "CHROME_IPC_LOGGING");
- bool logging_env_var_set = (requiredSize != 0);
- if (requiredSize <= 6) {
- char buffer[6];
- getenv_s(&requiredSize, buffer, sizeof(buffer), "CHROME_IPC_LOGGING");
- if (requiredSize && !strncmp("color", buffer, 6))
- enabled_color_ = true;
- }
- #else // !BUILDFLAG(IS_WIN)
- const char* ipc_logging = getenv("CHROME_IPC_LOGGING");
- bool logging_env_var_set = (ipc_logging != NULL);
- if (ipc_logging && !strcmp(ipc_logging, "color"))
- enabled_color_ = true;
- #endif // BUILDFLAG(IS_WIN)
- if (logging_env_var_set) {
- enabled_ = true;
- enabled_on_stderr_ = true;
- }
- }
- Logging::~Logging() {
- }
- Logging* Logging::GetInstance() {
- return base::Singleton<Logging>::get();
- }
- void Logging::SetConsumer(Consumer* consumer) {
- consumer_ = consumer;
- }
- void Logging::Enable() {
- enabled_ = true;
- }
- void Logging::Disable() {
- enabled_ = false;
- }
- void Logging::OnSendLogs() {
- queue_invoke_later_pending_ = false;
- if (!sender_)
- return;
- Message* msg = new Message(
- MSG_ROUTING_CONTROL, IPC_LOGGING_ID, Message::PRIORITY_NORMAL);
- WriteParam(msg, queued_logs_);
- queued_logs_.clear();
- sender_->Send(msg);
- }
- void Logging::SetIPCSender(IPC::Sender* sender) {
- sender_ = sender;
- }
- void Logging::OnReceivedLoggingMessage(const Message& message) {
- std::vector<LogData> data;
- base::PickleIterator iter(message);
- if (!ReadParam(&message, &iter, &data))
- return;
- for (size_t i = 0; i < data.size(); ++i) {
- Log(data[i]);
- }
- }
- void Logging::OnSendMessage(Message* message) {
- if (!Enabled())
- return;
- if (message->is_reply()) {
- LogData* data = message->sync_log_data();
- if (!data)
- return;
- // This is actually the delayed reply to a sync message. Create a string
- // of the output parameters, add it to the LogData that was earlier stashed
- // with the reply, and log the result.
- GenerateLogData(*message, data, true);
- Log(*data);
- delete data;
- message->set_sync_log_data(NULL);
- } else {
- // If the time has already been set (i.e. by ChannelProxy), keep that time
- // instead as it's more accurate.
- if (!message->sent_time())
- message->set_sent_time(Time::Now().ToInternalValue());
- }
- }
- void Logging::OnPreDispatchMessage(const Message& message) {
- message.set_received_time(Time::Now().ToInternalValue());
- }
- void Logging::OnPostDispatchMessage(const Message& message) {
- if (!Enabled() ||
- !message.sent_time() ||
- !message.received_time() ||
- message.dont_log())
- return;
- LogData data;
- GenerateLogData(message, &data, true);
- if (main_thread_->BelongsToCurrentThread()) {
- Log(data);
- } else {
- main_thread_->PostTask(
- FROM_HERE, base::BindOnce(&Logging::Log, base::Unretained(this), data));
- }
- }
- void Logging::GetMessageText(uint32_t type, std::string* name,
- const Message* message,
- std::string* params) {
- if (!log_function_map_)
- return;
- LogFunctionMap::iterator it = log_function_map_->find(type);
- if (it == log_function_map_->end()) {
- if (name) {
- *name = "[UNKNOWN MSG ";
- *name += base::NumberToString(type);
- *name += " ]";
- }
- return;
- }
- (*it->second)(name, message, params);
- }
- const char* Logging::ANSIEscape(ANSIColor color) {
- if (!enabled_color_)
- return "";
- switch (color) {
- case ANSI_COLOR_RESET:
- return "\033[m";
- case ANSI_COLOR_BLACK:
- return "\033[0;30m";
- case ANSI_COLOR_RED:
- return "\033[0;31m";
- case ANSI_COLOR_GREEN:
- return "\033[0;32m";
- case ANSI_COLOR_YELLOW:
- return "\033[0;33m";
- case ANSI_COLOR_BLUE:
- return "\033[0;34m";
- case ANSI_COLOR_MAGENTA:
- return "\033[0;35m";
- case ANSI_COLOR_CYAN:
- return "\033[0;36m";
- case ANSI_COLOR_WHITE:
- return "\033[0;37m";
- }
- return "";
- }
- Logging::ANSIColor Logging::DelayColor(double delay) {
- if (delay < 0.1)
- return ANSI_COLOR_GREEN;
- if (delay < 0.25)
- return ANSI_COLOR_BLACK;
- if (delay < 0.5)
- return ANSI_COLOR_YELLOW;
- return ANSI_COLOR_RED;
- }
- void Logging::Log(const LogData& data) {
- if (consumer_) {
- // We're in the browser process.
- consumer_->Log(data);
- } else {
- // We're in the renderer or plugin processes.
- if (sender_) {
- queued_logs_.push_back(data);
- if (!queue_invoke_later_pending_) {
- queue_invoke_later_pending_ = true;
- base::ThreadTaskRunnerHandle::Get()->PostDelayedTask(
- FROM_HERE,
- base::BindOnce(&Logging::OnSendLogs, base::Unretained(this)),
- base::Milliseconds(kLogSendDelayMs));
- }
- }
- }
- if (enabled_on_stderr_) {
- std::string message_name;
- if (data.message_name.empty()) {
- message_name = base::StringPrintf("[unknown type %d]", data.type);
- } else {
- message_name = data.message_name;
- }
- double receive_delay =
- (Time::FromInternalValue(data.receive) -
- Time::FromInternalValue(data.sent)).InSecondsF();
- double dispatch_delay =
- (Time::FromInternalValue(data.dispatch) -
- Time::FromInternalValue(data.sent)).InSecondsF();
- fprintf(stderr,
- "ipc %d %s %s%s %s%s\n %18.5f %s%18.5f %s%18.5f%s\n",
- data.routing_id,
- data.flags.c_str(),
- ANSIEscape(sender_ ? ANSI_COLOR_BLUE : ANSI_COLOR_CYAN),
- message_name.c_str(),
- ANSIEscape(ANSI_COLOR_RESET),
- data.params.c_str(),
- Time::FromInternalValue(data.sent).ToDoubleT(),
- ANSIEscape(DelayColor(receive_delay)),
- Time::FromInternalValue(data.receive).ToDoubleT(),
- ANSIEscape(DelayColor(dispatch_delay)),
- Time::FromInternalValue(data.dispatch).ToDoubleT(),
- ANSIEscape(ANSI_COLOR_RESET)
- );
- }
- }
- void GenerateLogData(const Message& message, LogData* data, bool get_params) {
- if (message.is_reply()) {
- // "data" should already be filled in.
- std::string params;
- Logging::GetMessageText(data->type, NULL, &message, ¶ms);
- if (!data->params.empty() && !params.empty())
- data->params += ", ";
- data->flags += " DR";
- data->params += params;
- } else {
- std::string flags;
- if (message.is_sync())
- flags = "S";
- if (message.is_reply())
- flags += "R";
- if (message.is_reply_error())
- flags += "E";
- std::string params, message_name;
- Logging::GetMessageText(message.type(), &message_name, &message,
- get_params ? ¶ms : NULL);
- data->routing_id = message.routing_id();
- data->type = message.type();
- data->flags = flags;
- data->sent = message.sent_time();
- data->receive = message.received_time();
- data->dispatch = Time::Now().ToInternalValue();
- data->params = params;
- data->message_name = message_name;
- }
- }
- }
- #endif // BUILDFLAG(IPC_MESSAGE_LOG_ENABLED)
|