Refactor WebRtcLoggingHandlerHost in preparation of automatic upload of WebRtcEventLogs.

chrome/browser/media/webrtc_text_log_handler.cc

Index: chrome/browser/media/webrtc_text_log_handler.cc
diff --git a/chrome/browser/media/webrtc_text_log_handler.cc b/chrome/browser/media/webrtc_text_log_handler.cc
new file mode 100644
index 0000000000000000000000000000000000000000..9e7f9ab17c2fdd55ec5740ff433819a18c8670c7
--- /dev/null
+++ b/chrome/browser/media/webrtc_text_log_handler.cc
@@ -0,0 +1,434 @@
+// Copyright 2016 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 "chrome/browser/media/webrtc_text_log_handler.h"
+
+#include <map>
+#include <string>
+#include <utility>
+#include <vector>
+
+#include "base/bind.h"
+#include "base/cpu.h"
+#include "base/logging.h"
+#include "base/strings/string_number_conversions.h"
+#include "base/strings/stringprintf.h"
+#include "base/sys_info.h"
+#include "base/time/time.h"
+#include "chrome/common/channel_info.h"
+#include "chrome/common/media/webrtc_logging_messages.h"
+#include "components/version_info/version_info.h"
+#include "content/public/browser/browser_thread.h"
+#include "content/public/browser/gpu_data_manager.h"
+#include "content/public/browser/render_process_host.h"
+#include "gpu/config/gpu_info.h"
+#include "net/base/ip_address.h"
+#include "net/base/network_change_notifier.h"
+#include "net/base/network_interfaces.h"
+
+#if defined(OS_LINUX)
+#include "base/linux_util.h"
+#endif
+
+#if defined(OS_MACOSX)
+#include "base/mac/mac_util.h"
+#endif
+
+#if defined(OS_CHROMEOS)
+#include "chromeos/system/statistics_provider.h"
+#endif
+
+using base::IntToString;
+using content::BrowserThread;
+
+namespace {
+void FormatMetaDataAsLogMessage(const MetaDataMap& meta_data,
+                                std::string* message) {
+  for (MetaDataMap::const_iterator it = meta_data.begin();
+       it != meta_data.end(); ++it) {
+    *message += it->first + ": " + it->second + '\n';
+  }
+  // Remove last '\n'.
+  message->resize(message->size() - 1);
+}
+
+// For privacy reasons when logging IP addresses. The returned "sensitive
+// string" is for release builds a string with the end stripped away. Last
+// octet for IPv4 and last 80 bits (5 groups) for IPv6. String will be
+// "1.2.3.x" and "1.2.3::" respectively. For debug builds, the string is
+// not stripped.
+std::string IPAddressToSensitiveString(const net::IPAddress& address) {
+#if defined(NDEBUG)
+  std::string sensitive_address;
+  switch (address.size()) {
+    case net::IPAddress::kIPv4AddressSize: {
+      sensitive_address = address.ToString();
+      size_t find_pos = sensitive_address.rfind('.');
+      if (find_pos == std::string::npos)
+        return std::string();
+      sensitive_address.resize(find_pos);
+      sensitive_address += ".x";
+      break;
+    }
+    case net::IPAddress::kIPv6AddressSize: {
+      // TODO(grunell): Create a string of format "1:2:3:x:x:x:x:x" to clarify
+      // that the end has been stripped out.
+      std::vector<uint8_t> bytes = address.bytes();
+      std::fill(bytes.begin() + 6, bytes.end(), 0);
+      net::IPAddress stripped_address(bytes);
+      sensitive_address = stripped_address.ToString();
+      break;
+    }
+    default: { break; }
+  }
+  return sensitive_address;
+#else
+  return address.ToString();
+#endif
+}
+}  // namespace
+
+WebRtcLogBuffer::WebRtcLogBuffer()
+    : buffer_(),
+      circular_(&buffer_[0], sizeof(buffer_), sizeof(buffer_) / 2, false),
+      read_only_(false) {}
+
+WebRtcLogBuffer::~WebRtcLogBuffer() {
+  DCHECK(read_only_ || thread_checker_.CalledOnValidThread());
+}
+
+void WebRtcLogBuffer::Log(const std::string& message) {
+  DCHECK(thread_checker_.CalledOnValidThread());
+  DCHECK(!read_only_);
+  circular_.Write(message.c_str(), message.length());
+  const char eol = '\n';
+  circular_.Write(&eol, 1);
+}
+
+PartialCircularBuffer WebRtcLogBuffer::Read() {
+  DCHECK(thread_checker_.CalledOnValidThread());
+  DCHECK(read_only_);
+  return PartialCircularBuffer(&buffer_[0], sizeof(buffer_));
+}
+
+void WebRtcLogBuffer::SetComplete() {
+  DCHECK(thread_checker_.CalledOnValidThread());
+  DCHECK(!read_only_) << "Already set? (programmer error)";
+  read_only_ = true;
+  // Detach from the current thread so that we can check reads on a different
+  // thread.  This is to make sure that Read()s still happen on one thread only.
+  thread_checker_.DetachFromThread();
+}
+
+WebRtcTextLogHandler::WebRtcTextLogHandler(int render_process_id)
+    : render_process_id_(render_process_id),
+      log_buffer_(),  // Should be created by StartLogging.
+      meta_data_(),   // Should be created by StartLogging.
+      stop_callback_(),
+      logging_state_(CLOSED),
+      logging_started_time_(base::Time()) {}
+
+WebRtcTextLogHandler::~WebRtcTextLogHandler() {
+  // If the log isn't closed that means we haven't decremented the log count
+  // in the LogUploader. It would also make us destroy the WebRtcLogBuffer
+  // on a different thread than it was created on.
+  DCHECK_EQ(CLOSED, logging_state_);
+  DCHECK(!log_buffer_.get());
+}
+
+void WebRtcTextLogHandler::SetMetaData(std::unique_ptr<MetaDataMap> meta_data,
+                                       const GenericDoneCallback& callback) {
+  DCHECK_CURRENTLY_ON(BrowserThread::IO);
+  DCHECK(!callback.is_null());
+
+  std::string error_message;
+  if (logging_state_ == LoggingState::CLOSED) {
+    if (!meta_data_.get())
+      meta_data_ = std::move(meta_data);
+  } else if (logging_state_ == LoggingState::STARTED) {
+    std::string meta_data_message;
+    FormatMetaDataAsLogMessage(*meta_data.get(), &meta_data_message);
+    LogToCircularBuffer(meta_data_message);
+  } else {
+    error_message = "Meta data must be set before stop or upload.";
+  }
+
+  if (error_message.empty() && meta_data.get()) {
+    // Keep the meta data around for uploading separately from the log.
+    for (const auto& it : *meta_data.get())
+      (*meta_data_.get())[it.first] = it.second;
+  }
+
+  FireGenericDoneCallback(callback, error_message.empty(), error_message);
+}
+
+void WebRtcTextLogHandler::StartLogging(const GenericDoneCallback& callback) {
+  DCHECK_CURRENTLY_ON(BrowserThread::IO);
+  DCHECK_EQ(CLOSED, logging_state_);
+  DCHECK(!callback.is_null());
+
+  logging_state_ = STARTING;
+
+  DCHECK(!log_buffer_.get());
+  log_buffer_.reset(new WebRtcLogBuffer());
+  if (!meta_data_.get())
+    meta_data_.reset(new MetaDataMap());
+
+  BrowserThread::PostTask(
+      BrowserThread::FILE, FROM_HERE,
+      base::Bind(&WebRtcTextLogHandler::LogInitialInfoOnFileThread, this,
+                 callback));
+}
+
+void WebRtcTextLogHandler::StartDone(const GenericDoneCallback& callback) {
+  DCHECK_CURRENTLY_ON(BrowserThread::IO);
+  DCHECK_EQ(STARTING, logging_state_);
+  DCHECK(!callback.is_null());
+
+  logging_started_time_ = base::Time::Now();
+  logging_state_ = STARTED;
+  FireGenericDoneCallback(callback, true, "");
+}
+
+void WebRtcTextLogHandler::StopLogging(const GenericDoneCallback& callback) {
+  DCHECK_CURRENTLY_ON(BrowserThread::IO);
+  DCHECK_EQ(STARTED, logging_state_);
+  DCHECK(!callback.is_null());
+
+  stop_callback_ = callback;
+  logging_state_ = STOPPING;
+
+  BrowserThread::PostTask(
+      BrowserThread::UI, FROM_HERE,
+      base::Bind(&WebRtcTextLogHandler::DisableBrowserProcessLoggingOnUIThread,
+                 this));
+}
+
+void WebRtcTextLogHandler::StopDone() {
+  DCHECK_CURRENTLY_ON(BrowserThread::IO);
+  DCHECK_EQ(STOPPING, logging_state_);
+  logging_started_time_ = base::Time();
+  logging_state_ = STOPPED;
+  FireGenericDoneCallback(stop_callback_, true, "");
+  stop_callback_.Reset();
+}
+
+void WebRtcTextLogHandler::DiscardLog() {
+  DCHECK_CURRENTLY_ON(BrowserThread::IO);
+  // TODO(terelius): This function should normally only be called when the log
+  // is in the STOPPED state. However, OnChannelClosing can potantially call
+  // this in other states as well (but will in those cases make sure that the
+  // LogUploader decreases it's log count. We might want to split this function
+  // into two, or rethink how OnChannelClosing works.
+  DCHECK_NE(CLOSED, logging_state_);
+  log_buffer_.reset();
+  meta_data_.reset();
+  logging_state_ = LoggingState::CLOSED;
+}
+
+void WebRtcTextLogHandler::ReleaseLog(
+    std::unique_ptr<WebRtcLogBuffer>* log_buffer,
+    std::unique_ptr<MetaDataMap>* meta_data) {
+  DCHECK_CURRENTLY_ON(BrowserThread::IO);
+  DCHECK_EQ(STOPPED, logging_state_);
+
+  log_buffer_->SetComplete();
+  *log_buffer = std::move(log_buffer_);
+  *meta_data = std::move(meta_data_);
+  log_buffer_.reset();
+  meta_data_.reset();
+  logging_state_ = LoggingState::CLOSED;
+}
+
+void WebRtcTextLogHandler::LogToCircularBuffer(const std::string& message) {
+  DCHECK_CURRENTLY_ON(BrowserThread::IO);
+  DCHECK_NE(logging_state_, LoggingState::CLOSED);
+  log_buffer_->Log(message);
+}
+
+void WebRtcTextLogHandler::LogMessage(const std::string& message) {
+  DCHECK_CURRENTLY_ON(BrowserThread::IO);
+  if (logging_state_ == STARTED) {
+    LogToCircularBuffer(WebRtcLoggingMessageData::Format(
+        message, base::Time::Now(), logging_started_time_));
+  }
+}
+
+void WebRtcTextLogHandler::LogWebRtcLoggingMessageData(
+    const WebRtcLoggingMessageData& message) {
+  DCHECK_CURRENTLY_ON(BrowserThread::IO);
+  LogToCircularBuffer(message.Format(logging_started_time_));
+}
+
+void WebRtcTextLogHandler::FireGenericDoneCallback(
+    const GenericDoneCallback& callback,
+    bool success,
+    const std::string& error_message) {
+  DCHECK_CURRENTLY_ON(BrowserThread::IO);
+  DCHECK(!callback.is_null());
+
+  if (error_message.empty()) {
+    DCHECK(success);
+    BrowserThread::PostTask(BrowserThread::UI, FROM_HERE,
+                            base::Bind(callback, success, error_message));
+    return;
+  }
+
+  DCHECK(!success);
+
+  // Add current logging state to error message.
+  std::string error_message_with_state(error_message);
+  switch (logging_state_) {
+    case LoggingState::CLOSED:
+      error_message_with_state += " State=closed.";
+      break;
+    case LoggingState::STARTING:
+      error_message_with_state += " State=starting.";
+      break;
+    case LoggingState::STARTED:
+      error_message_with_state += " State=started.";
+      break;
+    case LoggingState::STOPPING:
+      error_message_with_state += " State=stopping.";
+      break;
+    case LoggingState::STOPPED:
+      error_message_with_state += " State=stopped.";
+      break;
+  }
+
+  BrowserThread::PostTask(
+      BrowserThread::UI, FROM_HERE,
+      base::Bind(callback, success, error_message_with_state));
+}
+
+void WebRtcTextLogHandler::LogInitialInfoOnFileThread(
+    const GenericDoneCallback& callback) {
+  DCHECK_CURRENTLY_ON(BrowserThread::FILE);
+
+  net::NetworkInterfaceList network_list;
+  net::GetNetworkList(&network_list,
+                      net::EXCLUDE_HOST_SCOPE_VIRTUAL_INTERFACES);
+
+  BrowserThread::PostTask(
+      BrowserThread::IO, FROM_HERE,
+      base::Bind(&WebRtcTextLogHandler::LogInitialInfoOnIOThread, this,
+                 network_list, callback));
+}
+
+void WebRtcTextLogHandler::LogInitialInfoOnIOThread(
+    const net::NetworkInterfaceList& network_list,
+    const GenericDoneCallback& callback) {
+  DCHECK_CURRENTLY_ON(BrowserThread::IO);
+  if (logging_state_ != STARTING) {
+    FireGenericDoneCallback(callback, false, "Logging cancelled.");
+    return;
+  }
+
+  // Tell the the browser to enable logging. Log messages are recevied on the
+  // IO thread, so the initial info will finish to be written first.
+  // TODO(terelius): Once we have moved over to Mojo, we could tell the
+  // renderer to start logging here, but for the time being
+  // WebRtcLoggingHandlerHost::StartLogging will be responsible for sending
+  // that IPC message.
+  BrowserThread::PostTask(
+      BrowserThread::UI, FROM_HERE,
+      base::Bind(&WebRtcTextLogHandler::EnableBrowserProcessLoggingOnUIThread,
+                 this));
+
+  // Log start time (current time). We don't use base/i18n/time_formatting.h
+  // here because we don't want the format of the current locale.
+  base::Time::Exploded now = {0};
+  base::Time::Now().LocalExplode(&now);
+  LogToCircularBuffer(base::StringPrintf("Start %d-%02d-%02d %02d:%02d:%02d",
+                                         now.year, now.month, now.day_of_month,
+                                         now.hour, now.minute, now.second));
+
+  // Write metadata if received before logging started.
+  if (meta_data_.get() && !meta_data_->empty()) {
+    std::string info;
+    FormatMetaDataAsLogMessage(*meta_data_.get(), &info);
+    LogToCircularBuffer(info);
+  }
+
+  // Chrome version
+  LogToCircularBuffer("Chrome version: " + version_info::GetVersionNumber() +
+                      " " + chrome::GetChannelString());
+
+  // OS
+  LogToCircularBuffer(base::SysInfo::OperatingSystemName() + " " +
+                      base::SysInfo::OperatingSystemVersion() + " " +
+                      base::SysInfo::OperatingSystemArchitecture());
+#if defined(OS_LINUX)
+  LogToCircularBuffer("Linux distribution: " + base::GetLinuxDistro());
+#endif
+
+  // CPU
+  base::CPU cpu;
+  LogToCircularBuffer(
+      "Cpu: " + IntToString(cpu.family()) + "." + IntToString(cpu.model()) +
+      "." + IntToString(cpu.stepping()) + ", x" +
+      IntToString(base::SysInfo::NumberOfProcessors()) + ", " +
+      IntToString(base::SysInfo::AmountOfPhysicalMemoryMB()) + "MB");
+  std::string cpu_brand = cpu.cpu_brand();
+  // Workaround for crbug.com/249713.
+  // TODO(grunell): Remove workaround when bug is fixed.
+  size_t null_pos = cpu_brand.find('\0');
+  if (null_pos != std::string::npos)
+    cpu_brand.erase(null_pos);
+  LogToCircularBuffer("Cpu brand: " + cpu_brand);
+
+  // Computer model
+  std::string computer_model = "Not available";
+#if defined(OS_MACOSX)
+  computer_model = base::mac::GetModelIdentifier();
+#elif defined(OS_CHROMEOS)
+  chromeos::system::StatisticsProvider::GetInstance()->GetMachineStatistic(
+      chromeos::system::kHardwareClassKey, &computer_model);
+#endif
+  LogToCircularBuffer("Computer model: " + computer_model);
+
+  // GPU
+  gpu::GPUInfo gpu_info = content::GpuDataManager::GetInstance()->GetGPUInfo();
+  LogToCircularBuffer(
+      "Gpu: machine-model-name=" + gpu_info.machine_model_name +
+      ", machine-model-version=" + gpu_info.machine_model_version +
+      ", vendor-id=" + base::UintToString(gpu_info.gpu.vendor_id) +
+      ", device-id=" + base::UintToString(gpu_info.gpu.device_id) +
+      ", driver-vendor=" + gpu_info.driver_vendor + ", driver-version=" +
+      gpu_info.driver_version);
+  LogToCircularBuffer("OpenGL: gl-vendor=" + gpu_info.gl_vendor +
+                      ", gl-renderer=" + gpu_info.gl_renderer +
+                      ", gl-version=" + gpu_info.gl_version);
+
+  // Network interfaces
+  LogToCircularBuffer("Discovered " + base::SizeTToString(network_list.size()) +
+                      " network interfaces:");
+  for (net::NetworkInterfaceList::const_iterator it = network_list.begin();
+       it != network_list.end(); ++it) {
+    LogToCircularBuffer(
+        "Name: " + it->friendly_name + ", Address: " +
+        IPAddressToSensitiveString(it->address) + ", Type: " +
+        net::NetworkChangeNotifier::ConnectionTypeToString(it->type));
+  }
+
+  StartDone(callback);
+}
+
+void WebRtcTextLogHandler::EnableBrowserProcessLoggingOnUIThread() {
+  DCHECK_CURRENTLY_ON(BrowserThread::UI);
+  content::RenderProcessHost* host =
+      content::RenderProcessHost::FromID(render_process_id_);
+  if (host) {
+    host->SetWebRtcLogMessageCallback(
+        base::Bind(&WebRtcTextLogHandler::LogMessage, this));
+  }
+}
+
+void WebRtcTextLogHandler::DisableBrowserProcessLoggingOnUIThread() {
+  DCHECK_CURRENTLY_ON(BrowserThread::UI);
+  content::RenderProcessHost* host =
+      content::RenderProcessHost::FromID(render_process_id_);
+  if (host)
+    host->ClearWebRtcLogMessageCallback();
+}