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..6776ee9f06088c4938501b1d89cd8c7e56fbb0a4
--- /dev/null
+++ b/chrome/browser/media/webrtc_text_log_handler.cc
@@ -0,0 +1,508 @@
+// 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/browser/media/webrtc_log_uploader.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 {
+std::string FormatMetaDataAsLogMessage(const MetaDataMap& meta_data) {
+  std::string message;
+  for (MetaDataMap::const_iterator it = meta_data.begin();

[magjed_chromium, 2016/07/22 09:30:31]

Use a range based for loop instead.

[terelius-chromium, 2016/07/26 09:51:41]

Good point. Done.

+       it != meta_data.end(); ++it) {
+    message += it->first + ": " + it->second + '\n';
+  }
+  // Remove last '\n'.
+  message.resize(message.size() - 1);

[magjed_chromium, 2016/07/22 09:30:31]

Use message.pop_back() instead.

[terelius-chromium, 2016/07/26 09:51:41]

I don't get pop_back to compile. Is our compiler setup C++11 compliant?

There seems to be an index-out-of-range issue if the function is called with an
empty map. Not sure whether that can happen, but I added a check.

[magjed_chromium, 2016/07/27 11:54:38]

We use other C++11 stuff at least. Skip pop_back then if it's causing trouble.

+  return message;
+}
+
+// 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.
+  DCHECK(logging_state_ == CLOSED || logging_state_ == CHANNEL_CLOSING);
+  DCHECK(!log_buffer_);
+}
+
+void WebRtcTextLogHandler::SetMetaData(std::unique_ptr<MetaDataMap> meta_data,
+                                       const GenericDoneCallback& callback) {
+  DCHECK_CURRENTLY_ON(BrowserThread::IO);
+  DCHECK(!callback.is_null());
+
+  if (logging_state_ != CLOSED && logging_state_ != STARTED) {
+    std::string error_message = "Meta data must be set before stop or upload.";
+    FireGenericDoneCallback(callback, false, error_message);
+    return;
+  }
+
+  if (logging_state_ == LoggingState::STARTED) {
+    std::string meta_data_message =
+        FormatMetaDataAsLogMessage(*meta_data.get());

[magjed_chromium, 2016/07/22 09:30:31]

Replace *x.get() with just *x, here and in all other places.

[terelius-chromium, 2016/07/26 09:51:41]

Done.

+    LogToCircularBuffer(meta_data_message);
+  }
+
+  if (!meta_data_) {
+    // If no meta data has been set previously, set it now.
+    meta_data_ = std::move(meta_data);
+  } else if (meta_data) {
+    // If there is existing meta data, update it and any new fields. The meta
+    // data is kept around to be uploaded separately from the log.
+    for (const auto& it : *meta_data.get())
+      (*meta_data_.get())[it.first] = it.second;
+  }
+
+  FireGenericDoneCallback(callback, true, "");
+}
+
+bool WebRtcTextLogHandler::StartLogging(WebRtcLogUploader* log_uploader,
+                                        const GenericDoneCallback& callback) {
+  DCHECK_CURRENTLY_ON(BrowserThread::IO);
+  DCHECK(!callback.is_null());
+
+  if (logging_state_ == CHANNEL_CLOSING) {
+    FireGenericDoneCallback(callback, false, "The renderer is closing.");
+    return false;
+  }
+
+  if (logging_state_ != CLOSED) {
+    FireGenericDoneCallback(callback, false, "A log is already open.");
+    return false;
+  }
+
+  if (!log_uploader->ApplyForStartLogging()) {
+    FireGenericDoneCallback(callback, false,
+                            "Cannot start, maybe the maximum number of "
+                            "simultaneuos logs has been reached.");
+    return false;
+  }
+
+  logging_state_ = STARTING;
+
+  DCHECK(!log_buffer_);
+  log_buffer_.reset(new WebRtcLogBuffer());
+  if (!meta_data_)
+    meta_data_.reset(new MetaDataMap());
+
+  BrowserThread::PostTask(
+      BrowserThread::FILE, FROM_HERE,
+      base::Bind(&WebRtcTextLogHandler::LogInitialInfoOnFileThread, this,
+                 callback));
+  return true;
+}
+
+void WebRtcTextLogHandler::StartDone(const GenericDoneCallback& callback) {
+  DCHECK_CURRENTLY_ON(BrowserThread::IO);
+  DCHECK(!callback.is_null());
+
+  if (logging_state_ == CHANNEL_CLOSING) {
+    FireGenericDoneCallback(callback, false,
+                            "Failed to start log. Renderer is closing.");
+    return;
+  }
+
+  DCHECK_EQ(STARTING, logging_state_);
+
+  logging_started_time_ = base::Time::Now();
+  logging_state_ = STARTED;
+  FireGenericDoneCallback(callback, true, "");
+}
+
+bool WebRtcTextLogHandler::StopLogging(const GenericDoneCallback& callback) {
+  DCHECK_CURRENTLY_ON(BrowserThread::IO);
+  DCHECK(!callback.is_null());
+
+  if (logging_state_ == CHANNEL_CLOSING) {
+    FireGenericDoneCallback(callback, false,
+                            "Can't stop log. Renderer is closing.");
+    return false;
+  }
+
+  if (logging_state_ != STARTED) {
+    FireGenericDoneCallback(callback, false, "Logging not started.");
+    return false;
+  }
+
+  stop_callback_ = callback;
+  logging_state_ = STOPPING;
+
+  BrowserThread::PostTask(
+      BrowserThread::UI, FROM_HERE,
+      base::Bind(&WebRtcTextLogHandler::DisableBrowserProcessLoggingOnUIThread,
+                 this));
+  return true;
+}
+
+void WebRtcTextLogHandler::StopDone() {
+  DCHECK_CURRENTLY_ON(BrowserThread::IO);
+  DCHECK_EQ(STOPPING, logging_state_);
+  // If we aren't in STOPPING state, then there is a bug in the caller, since
+  // it is responsible for checking the state before making the call. If we do
+  // enter here in a bad state, then we can't use the stop_callback_ or we
+  // might fire the same callback multiple times.
+  if (logging_state_ == STOPPING) {
+    logging_started_time_ = base::Time();
+    logging_state_ = STOPPED;
+    FireGenericDoneCallback(stop_callback_, true, "");
+    stop_callback_.Reset();
+  }
+}
+
+void WebRtcTextLogHandler::ChannelClosing() {
+  DCHECK_CURRENTLY_ON(BrowserThread::IO);
+
+  if (logging_state_ == STARTING || logging_state_ == STARTED) {
+    logging_state_ = LoggingState::CHANNEL_CLOSING;
+    BrowserThread::PostTask(
+        BrowserThread::UI, FROM_HERE,
+        base::Bind(
+            &WebRtcTextLogHandler::DisableBrowserProcessLoggingOnUIThread,
+            this));
+  } else {
+    logging_state_ = LoggingState::CHANNEL_CLOSING;
+  }
+}
+
+void WebRtcTextLogHandler::DiscardLog() {
+  DCHECK_CURRENTLY_ON(BrowserThread::IO);
+  DCHECK(logging_state_ == STOPPED || logging_state_ == CHANNEL_CLOSING);
+  log_buffer_.reset();
+  meta_data_.reset();
+  if (logging_state_ != CHANNEL_CLOSING)
+    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(logging_state_ == STOPPED || logging_state_ == CHANNEL_CLOSING);
+
+  log_buffer_->SetComplete();
+  *log_buffer = std::move(log_buffer_);
+  *meta_data = std::move(meta_data_);
+  log_buffer_.reset();

[magjed_chromium, 2016/07/22 09:30:31]

std::move is enough, you don't need to reset as well.

[terelius-chromium, 2016/07/26 09:51:41]

True, but I prefer to be explicit here since it is important
that the log_buffer_ does not point to anything, rather that
pointing to a dummy object for example. It also makes the
similarity between ReleaseLog and DiscardLog more apparent. 

I will change if you insist.

+  meta_data_.reset();
+  if (logging_state_ != CHANNEL_CLOSING)
+    logging_state_ = LoggingState::CLOSED;
+}
+
+void WebRtcTextLogHandler::LogToCircularBuffer(const std::string& message) {
+  DCHECK_CURRENTLY_ON(BrowserThread::IO);
+  DCHECK_NE(logging_state_, CLOSED);
+  if (log_buffer_) {
+    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_));
+}
+
+bool WebRtcTextLogHandler::ExpectLoggingStateStopped(
+    const GenericDoneCallback& callback) {
+  DCHECK_CURRENTLY_ON(BrowserThread::IO);
+  if (logging_state_ != STOPPED) {
+    FireGenericDoneCallback(callback, false,
+                            "Logging not stopped or no log open.");
+    return false;
+  }
+  return true;
+}
+
+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;
+    case LoggingState::CHANNEL_CLOSING:
+      error_message_with_state += " State=channel closing.";
+      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 received 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_ && !meta_data_->empty()) {
+    std::string info = FormatMetaDataAsLogMessage(*meta_data_.get());
+    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();

[magjed_chromium, 2016/07/22 09:30:31]

nit: use range based for loop instead.

[terelius-chromium, 2016/07/26 09:51:41]

Done.

+       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();
+}