michael@0: // Copyright (c) 2006-2008 The Chromium Authors. All rights reserved.
michael@0: // Use of this source code is governed by a BSD-style license that can be
michael@0: // found in the LICENSE file.
michael@0: 
michael@0: #include "chrome/common/ipc_logging.h"
michael@0: 
michael@0: #if defined(OS_POSIX)
michael@0: #ifdef IPC_MESSAGE_LOG_ENABLED
michael@0: // This will cause render_messages.h etc to define ViewMsgLog and friends.
michael@0: #define IPC_MESSAGE_MACROS_LOG_ENABLED
michael@0: #endif
michael@0: #endif
michael@0: 
michael@0: #include "base/command_line.h"
michael@0: #include "base/logging.h"
michael@0: #include "base/message_loop.h"
michael@0: #include "base/string_util.h"
michael@0: #include "base/thread.h"
michael@0: #include "base/time.h"
michael@0: #include "base/waitable_event.h"
michael@0: #include "base/waitable_event_watcher.h"
michael@0: #include "chrome/common/chrome_switches.h"
michael@0: #include "chrome/common/ipc_sync_message.h"
michael@0: #include "chrome/common/ipc_message_utils.h"
michael@0: 
michael@0: #if defined(OS_POSIX)
michael@0: #include "base/string_util.h"
michael@0: #include <unistd.h>
michael@0: #endif
michael@0: 
michael@0: #ifdef IPC_MESSAGE_LOG_ENABLED
michael@0: 
michael@0: using base::Time;
michael@0: 
michael@0: // IPC::Logging is allocated as a singleton, so we don't need any kind of
michael@0: // special retention program.
michael@0: template <>
michael@0: struct RunnableMethodTraits<IPC::Logging> {
michael@0:   static void RetainCallee(IPC::Logging*) {}
michael@0:   static void ReleaseCallee(IPC::Logging*) {}
michael@0: };
michael@0: 
michael@0: namespace IPC {
michael@0: 
michael@0: const wchar_t kLoggingEventName[] = L"ChromeIPCLog.%d";
michael@0: const int kLogSendDelayMs = 100;
michael@0: 
michael@0: // We use a pointer to the function table to avoid any linker dependencies on
michael@0: // all the traits used as IPC message parameters.
michael@0: Logging::LogFunction *Logging::log_function_mapping_;
michael@0: 
michael@0: Logging::Logging()
michael@0:     : logging_event_on_(NULL),
michael@0:       logging_event_off_(NULL),
michael@0:       enabled_(false),
michael@0:       queue_invoke_later_pending_(false),
michael@0:       sender_(NULL),
michael@0:       main_thread_(MessageLoop::current()),
michael@0:       consumer_(NULL) {
michael@0:   // Create an event for this browser instance that's set when logging is
michael@0:   // enabled, so child processes can know when logging is enabled.
michael@0: 
michael@0: #if defined(OS_WIN)
michael@0:   // On Windows we have a couple of named events which switch logging on and
michael@0:   // off.
michael@0:   int browser_pid;
michael@0:   const CommandLine& parsed_command_line = *CommandLine::ForCurrentProcess();
michael@0:   std::wstring process_type =
michael@0:     parsed_command_line.GetSwitchValue(switches::kProcessType);
michael@0:   if (process_type.empty()) {
michael@0:     browser_pid = GetCurrentProcessId();
michael@0:   } else {
michael@0:     std::wstring channel_name =
michael@0:         parsed_command_line.GetSwitchValue(switches::kProcessChannelID);
michael@0: 
michael@0:     browser_pid = _wtoi(channel_name.c_str());
michael@0:     DCHECK(browser_pid != 0);
michael@0:   }
michael@0: 
michael@0:   std::wstring event_name = GetEventName(browser_pid, true);
michael@0:   logging_event_on_.reset(new base::WaitableEvent(
michael@0:       CreateEventW(NULL, TRUE, FALSE, event_name.c_str())));
michael@0: 
michael@0:   event_name = GetEventName(browser_pid, false);
michael@0:   logging_event_off_.reset(new base::WaitableEvent(
michael@0:       CreateEventW(NULL, TRUE, FALSE, event_name.c_str())));
michael@0: 
michael@0:   RegisterWaitForEvent(true);
michael@0: #endif
michael@0: 
michael@0:   MessageLoop::current()->AddDestructionObserver(this);
michael@0: }
michael@0: 
michael@0: Logging::~Logging() {
michael@0: }
michael@0: 
michael@0: Logging* Logging::current() {
michael@0:   return Singleton<Logging>::get();
michael@0: }
michael@0: 
michael@0: void Logging::RegisterWaitForEvent(bool enabled) {
michael@0:   watcher_.StopWatching();
michael@0:   watcher_.StartWatching(
michael@0:       enabled ? logging_event_on_.get() : logging_event_off_.get(), this);
michael@0: }
michael@0: 
michael@0: void Logging::OnWaitableEventSignaled(base::WaitableEvent* event) {
michael@0:   enabled_ = event == logging_event_on_.get();
michael@0:   RegisterWaitForEvent(!enabled_);
michael@0: }
michael@0: 
michael@0: void Logging::WillDestroyCurrentMessageLoop() {
michael@0:   watcher_.StopWatching();
michael@0: }
michael@0: 
michael@0: void Logging::SetLoggerFunctions(LogFunction *functions) {
michael@0:   log_function_mapping_ = functions;
michael@0: }
michael@0: 
michael@0: #if defined(OS_WIN)
michael@0: std::wstring Logging::GetEventName(bool enabled) {
michael@0:   return current()->GetEventName(GetCurrentProcessId(), enabled);
michael@0: }
michael@0: #endif
michael@0: 
michael@0: std::wstring Logging::GetEventName(int browser_pid, bool enabled) {
michael@0:   std::wstring result = StringPrintf(kLoggingEventName, browser_pid);
michael@0:   result += enabled ? L"on" : L"off";
michael@0:   return result;
michael@0: }
michael@0: 
michael@0: void Logging::SetConsumer(Consumer* consumer) {
michael@0:   consumer_ = consumer;
michael@0: }
michael@0: 
michael@0: void Logging::Enable() {
michael@0:   logging_event_off_->Reset();
michael@0:   logging_event_on_->Signal();
michael@0: }
michael@0: 
michael@0: void Logging::Disable() {
michael@0:   logging_event_on_->Reset();
michael@0:   logging_event_off_->Signal();
michael@0: }
michael@0: 
michael@0: void Logging::OnSendLogs() {
michael@0:   queue_invoke_later_pending_ = false;
michael@0:   if (!sender_)
michael@0:     return;
michael@0: 
michael@0:   Message* msg = new Message(
michael@0:       MSG_ROUTING_CONTROL, IPC_LOGGING_ID, Message::PRIORITY_NORMAL);
michael@0:   WriteParam(msg, queued_logs_);
michael@0:   queued_logs_.clear();
michael@0:   sender_->Send(msg);
michael@0: }
michael@0: 
michael@0: void Logging::SetIPCSender(IPC::Message::Sender* sender) {
michael@0:   sender_ = sender;
michael@0: }
michael@0: 
michael@0: void Logging::OnReceivedLoggingMessage(const Message& message) {
michael@0:   std::vector<LogData> data;
michael@0:   void* iter = NULL;
michael@0:   if (!ReadParam(&message, &iter, &data))
michael@0:     return;
michael@0: 
michael@0:   for (size_t i = 0; i < data.size(); ++i) {
michael@0:     Log(data[i]);
michael@0:   }
michael@0: }
michael@0: 
michael@0: void Logging::OnSendMessage(Message* message, const std::wstring& channel_id) {
michael@0:   if (!Enabled())
michael@0:     return;
michael@0: 
michael@0:   if (message->is_reply()) {
michael@0:     LogData* data = message->sync_log_data();
michael@0:     if (!data)
michael@0:       return;
michael@0: 
michael@0:     // This is actually the delayed reply to a sync message.  Create a string
michael@0:     // of the output parameters, add it to the LogData that was earlier stashed
michael@0:     // with the reply, and log the result.
michael@0:     data->channel = channel_id;
michael@0:     GenerateLogData(L"", *message, data);
michael@0:     Log(*data);
michael@0:     delete data;
michael@0:     message->set_sync_log_data(NULL);
michael@0:   } else {
michael@0:     // If the time has already been set (i.e. by ChannelProxy), keep that time
michael@0:     // instead as it's more accurate.
michael@0:     if (!message->sent_time())
michael@0:       message->set_sent_time(Time::Now().ToInternalValue());
michael@0:   }
michael@0: }
michael@0: 
michael@0: void Logging::OnPreDispatchMessage(const Message& message) {
michael@0:   message.set_received_time(Time::Now().ToInternalValue());
michael@0: }
michael@0: 
michael@0: void Logging::OnPostDispatchMessage(const Message& message,
michael@0:                                     const std::wstring& channel_id) {
michael@0:   if (!Enabled() ||
michael@0: #if defined(OS_WIN)
michael@0:       !message.sent_time() ||
michael@0: #endif
michael@0:       message.dont_log())
michael@0:     return;
michael@0: 
michael@0:   LogData data;
michael@0:   GenerateLogData(channel_id, message, &data);
michael@0: 
michael@0:   if (MessageLoop::current() == main_thread_) {
michael@0:     Log(data);
michael@0:   } else {
michael@0:     main_thread_->PostTask(FROM_HERE, NewRunnableMethod(
michael@0:         this, &Logging::Log, data));
michael@0:   }
michael@0: }
michael@0: 
michael@0: void Logging::GetMessageText(uint16_t type, std::wstring* name,
michael@0:                              const Message* message,
michael@0:                              std::wstring* params) {
michael@0:   if (!log_function_mapping_)
michael@0:     return;
michael@0: 
michael@0:   int message_class = type >> 12;
michael@0:   if (log_function_mapping_[message_class] != NULL) {
michael@0:     log_function_mapping_[message_class](type, name, message, params);
michael@0:   } else {
michael@0:     DLOG(INFO) << "No logger function associated with message class " <<
michael@0:         message_class;
michael@0:   }
michael@0: }
michael@0: 
michael@0: void Logging::Log(const LogData& data) {
michael@0: #if defined(OS_WIN)
michael@0:   if (consumer_) {
michael@0:     // We're in the browser process.
michael@0:     consumer_->Log(data);
michael@0:   } else {
michael@0:     // We're in the renderer or plugin processes.
michael@0:     if (sender_) {
michael@0:       queued_logs_.push_back(data);
michael@0:       if (!queue_invoke_later_pending_) {
michael@0:         queue_invoke_later_pending_ = true;
michael@0:         MessageLoop::current()->PostDelayedTask(FROM_HERE, NewRunnableMethod(
michael@0:             this, &Logging::OnSendLogs), kLogSendDelayMs);
michael@0:       }
michael@0:     }
michael@0:   }
michael@0: #elif defined(OS_POSIX)
michael@0:   // On POSIX, for now, we just dump the log to stderr
michael@0:   fprintf(stderr, "ipc %s %d %d %s %s %s\n",
michael@0:           WideToUTF8(data.channel).c_str(),
michael@0:           data.routing_id,
michael@0:           data.type,
michael@0:           WideToUTF8(data.flags).c_str(),
michael@0:           WideToUTF8(data.message_name).c_str(),
michael@0:           WideToUTF8(data.params).c_str());
michael@0: #endif
michael@0: }
michael@0: 
michael@0: void GenerateLogData(const std::wstring& channel, const Message& message,
michael@0:                      LogData* data) {
michael@0:   if (message.is_reply()) {
michael@0:     // "data" should already be filled in.
michael@0:     std::wstring params;
michael@0:     Logging::GetMessageText(data->type, NULL, &message, &params);
michael@0: 
michael@0:     if (!data->params.empty() && !params.empty())
michael@0:       data->params += L", ";
michael@0: 
michael@0:     data->flags += L" DR";
michael@0: 
michael@0:     data->params += params;
michael@0:   } else {
michael@0:     std::wstring flags;
michael@0:     if (message.is_sync())
michael@0:       flags = L"S";
michael@0: 
michael@0:     if (message.is_reply())
michael@0:       flags += L"R";
michael@0: 
michael@0:     if (message.is_reply_error())
michael@0:       flags += L"E";
michael@0: 
michael@0:     std::wstring params, message_name;
michael@0:     Logging::GetMessageText(message.type(), &message_name, &message, &params);
michael@0: 
michael@0:     data->channel = channel;
michael@0:     data->routing_id = message.routing_id();
michael@0:     data->type = message.type();
michael@0:     data->flags = flags;
michael@0:     data->sent = message.sent_time();
michael@0:     data->receive = message.received_time();
michael@0:     data->dispatch = Time::Now().ToInternalValue();
michael@0:     data->params = params;
michael@0:     data->message_name = message_name;
michael@0:   }
michael@0: }
michael@0: 
michael@0: }
michael@0: 
michael@0: #endif  // IPC_MESSAGE_LOG_ENABLED