webrtc_logging_handler_host.cc revision c5cede9ae108bb15f6b7a8aea21c7e1fefa2834c 
1// Copyright 2013 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
5#include "chrome/browser/media/webrtc_logging_handler_host.h"
6
7#include <string>
8
9#include "base/bind.h"
10#include "base/command_line.h"
11#include "base/cpu.h"
12#include "base/file_util.h"
13#include "base/logging.h"
14#include "base/prefs/pref_service.h"
15#include "base/strings/string_number_conversions.h"
16#include "base/sys_info.h"
17#include "base/time/time.h"
18#include "chrome/browser/browser_process.h"
19#include "chrome/browser/chromeos/settings/cros_settings.h"
20#include "chrome/browser/media/webrtc_log_list.h"
21#include "chrome/browser/media/webrtc_log_uploader.h"
22#include "chrome/browser/profiles/profile.h"
23#include "chrome/common/chrome_switches.h"
24#include "chrome/common/media/webrtc_logging_messages.h"
25#include "chrome/common/partial_circular_buffer.h"
26#include "chrome/common/pref_names.h"
27#include "chromeos/settings/cros_settings_names.h"
28#include "content/public/browser/browser_thread.h"
29#include "content/public/browser/content_browser_client.h"
30#include "content/public/browser/gpu_data_manager.h"
31#include "content/public/browser/render_process_host.h"
32#include "gpu/config/gpu_info.h"
33#include "net/base/address_family.h"
34#include "net/url_request/url_request_context_getter.h"
35
36#if defined(OS_LINUX)
37#include "base/linux_util.h"
38#endif
39
40#if defined(OS_MACOSX)
41#include "base/mac/mac_util.h"
42#endif
43
44#if defined(OS_CHROMEOS)
45#include "chromeos/system/statistics_provider.h"
46#endif
47
48using base::IntToString;
49using content::BrowserThread;
50
51
52#if defined(OS_ANDROID)
53const size_t kWebRtcLogSize = 1 * 1024 * 1024;  // 1 MB
54#else
55const size_t kWebRtcLogSize = 6 * 1024 * 1024;  // 6 MB
56#endif
57
58namespace {
59
60const char kLogNotStoppedOrNoLogOpen[] =
61    "Logging not stopped or no log open.";
62
63// For privacy reasons when logging IP addresses. The returned "sensitive
64// string" is for release builds a string with the end stripped away. Last
65// octet for IPv4 and last 80 bits (5 groups) for IPv6. String will be
66// "1.2.3.x" and "1.2.3::" respectively. For debug builds, the string is
67// not stripped.
68std::string IPAddressToSensitiveString(const net::IPAddressNumber& address) {
69#if defined(NDEBUG)
70  std::string sensitive_address;
71  switch (net::GetAddressFamily(address)) {
72    case net::ADDRESS_FAMILY_IPV4: {
73      sensitive_address = net::IPAddressToString(address);
74      size_t find_pos = sensitive_address.rfind('.');
75      if (find_pos == std::string::npos)
76        return std::string();
77      sensitive_address.resize(find_pos);
78      sensitive_address += ".x";
79      break;
80    }
81    case net::ADDRESS_FAMILY_IPV6: {
82      // TODO(grunell): Create a string of format "1:2:3:x:x:x:x:x" to clarify
83      // that the end has been stripped out.
84      net::IPAddressNumber sensitive_address_number = address;
85      sensitive_address_number.resize(net::kIPv6AddressSize - 10);
86      sensitive_address_number.resize(net::kIPv6AddressSize, 0);
87      sensitive_address = net::IPAddressToString(sensitive_address_number);
88      break;
89    }
90    case net::ADDRESS_FAMILY_UNSPECIFIED: {
91      break;
92    }
93  }
94  return sensitive_address;
95#else
96  return net::IPAddressToString(address);
97#endif
98}
99
100void FormatMetaDataAsLogMessage(
101    const MetaDataMap& meta_data,
102    std::string* message) {
103  for (MetaDataMap::const_iterator it = meta_data.begin();
104       it != meta_data.end(); ++it) {
105    *message += it->first + ": " + it->second + '\n';
106  }
107  // Remove last '\n'.
108  message->resize(message->size() - 1);
109}
110
111}  // namespace
112
113WebRtcLoggingHandlerHost::WebRtcLoggingHandlerHost(Profile* profile)
114    : BrowserMessageFilter(WebRtcLoggingMsgStart),
115      profile_(profile),
116      logging_state_(CLOSED),
117      upload_log_on_render_close_(false) {
118  DCHECK(profile_);
119}
120
121WebRtcLoggingHandlerHost::~WebRtcLoggingHandlerHost() {}
122
123void WebRtcLoggingHandlerHost::SetMetaData(
124    const MetaDataMap& meta_data,
125    const GenericDoneCallback& callback) {
126  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
127  DCHECK(!callback.is_null());
128
129  std::string error_message;
130  if (logging_state_ == CLOSED) {
131    meta_data_ = meta_data;
132  } else if (logging_state_ == STARTED) {
133    meta_data_ = meta_data;
134    std::string meta_data_message;
135    FormatMetaDataAsLogMessage(meta_data_, &meta_data_message);
136    LogToCircularBuffer(meta_data_message);
137  } else {
138    error_message = "Meta data must be set before stop or upload.";
139  }
140  bool success = error_message.empty();
141  content::BrowserThread::PostTask(content::BrowserThread::UI, FROM_HERE,
142                                   base::Bind(callback, success,
143                                              error_message));
144}
145
146void WebRtcLoggingHandlerHost::StartLogging(
147    const GenericDoneCallback& callback) {
148  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
149  DCHECK(!callback.is_null());
150
151  start_callback_ = callback;
152  if (logging_state_ != CLOSED) {
153    FireGenericDoneCallback(&start_callback_, false, "A log is already open");
154    return;
155  }
156  logging_state_ = STARTING;
157  BrowserThread::PostTask(BrowserThread::UI, FROM_HERE, base::Bind(
158      &WebRtcLoggingHandlerHost::StartLoggingIfAllowed, this));
159}
160
161void WebRtcLoggingHandlerHost::StopLogging(
162    const GenericDoneCallback& callback) {
163  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
164  DCHECK(!callback.is_null());
165
166  stop_callback_ = callback;
167  if (logging_state_ != STARTED) {
168    FireGenericDoneCallback(&stop_callback_, false, "Logging not started");
169    return;
170  }
171  logging_state_ = STOPPING;
172  Send(new WebRtcLoggingMsg_StopLogging());
173}
174
175void WebRtcLoggingHandlerHost::UploadLog(const UploadDoneCallback& callback) {
176  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
177  DCHECK(!callback.is_null());
178
179  if (logging_state_ != STOPPED) {
180    if (!callback.is_null()) {
181      content::BrowserThread::PostTask(content::BrowserThread::UI, FROM_HERE,
182          base::Bind(callback, false, "", kLogNotStoppedOrNoLogOpen));
183    }
184    return;
185  }
186  upload_callback_ = callback;
187  content::BrowserThread::PostTaskAndReplyWithResult(
188      content::BrowserThread::FILE,
189      FROM_HERE,
190      base::Bind(&WebRtcLoggingHandlerHost::GetLogDirectoryAndEnsureExists,
191                 this),
192      base::Bind(&WebRtcLoggingHandlerHost::TriggerUploadLog, this));
193}
194
195void WebRtcLoggingHandlerHost::UploadLogDone() {
196  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
197  logging_state_ = CLOSED;
198}
199
200void WebRtcLoggingHandlerHost::DiscardLog(const GenericDoneCallback& callback) {
201  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
202  DCHECK(!callback.is_null());
203
204  GenericDoneCallback discard_callback = callback;
205  if (logging_state_ != STOPPED) {
206    FireGenericDoneCallback(&discard_callback, false,
207                            kLogNotStoppedOrNoLogOpen);
208    return;
209  }
210  g_browser_process->webrtc_log_uploader()->LoggingStoppedDontUpload();
211  circular_buffer_.reset();
212  log_buffer_.reset();
213  logging_state_ = CLOSED;
214  FireGenericDoneCallback(&discard_callback, true, "");
215}
216
217void WebRtcLoggingHandlerHost::LogMessage(const std::string& message) {
218  BrowserThread::PostTask(
219      BrowserThread::IO,
220      FROM_HERE,
221      base::Bind(
222          &WebRtcLoggingHandlerHost::AddLogMessageFromBrowser,
223          this,
224          WebRtcLoggingMessageData(base::Time::Now(), message)));
225}
226
227void WebRtcLoggingHandlerHost::OnChannelClosing() {
228  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
229  if (logging_state_ == STARTED || logging_state_ == STOPPED) {
230    if (upload_log_on_render_close_) {
231      logging_state_ = STOPPED;
232      logging_started_time_ = base::Time();
233      content::BrowserThread::PostTaskAndReplyWithResult(
234          content::BrowserThread::FILE,
235          FROM_HERE,
236          base::Bind(&WebRtcLoggingHandlerHost::GetLogDirectoryAndEnsureExists,
237                     this),
238          base::Bind(&WebRtcLoggingHandlerHost::TriggerUploadLog, this));
239    } else {
240      g_browser_process->webrtc_log_uploader()->LoggingStoppedDontUpload();
241    }
242  }
243  content::BrowserMessageFilter::OnChannelClosing();
244}
245
246void WebRtcLoggingHandlerHost::OnDestruct() const {
247  BrowserThread::DeleteOnIOThread::Destruct(this);
248}
249
250bool WebRtcLoggingHandlerHost::OnMessageReceived(const IPC::Message& message,
251                                                 bool* message_was_ok) {
252  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
253  bool handled = true;
254  IPC_BEGIN_MESSAGE_MAP_EX(WebRtcLoggingHandlerHost, message, *message_was_ok)
255    IPC_MESSAGE_HANDLER(WebRtcLoggingMsg_AddLogMessages, OnAddLogMessages)
256    IPC_MESSAGE_HANDLER(WebRtcLoggingMsg_LoggingStopped,
257                        OnLoggingStoppedInRenderer)
258    IPC_MESSAGE_UNHANDLED(handled = false)
259  IPC_END_MESSAGE_MAP_EX()
260
261  return handled;
262}
263
264void WebRtcLoggingHandlerHost::AddLogMessageFromBrowser(
265    const WebRtcLoggingMessageData& message) {
266  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
267  if (logging_state_ == STARTED)
268    LogToCircularBuffer(message.Format(logging_started_time_));
269}
270
271void WebRtcLoggingHandlerHost::OnAddLogMessages(
272    const std::vector<WebRtcLoggingMessageData>& messages) {
273  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
274  if (logging_state_ == STARTED || logging_state_ == STOPPING) {
275    for (size_t i = 0; i < messages.size(); ++i) {
276      LogToCircularBuffer(messages[i].Format(logging_started_time_));
277    }
278  }
279}
280
281void WebRtcLoggingHandlerHost::OnLoggingStoppedInRenderer() {
282  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
283  if (logging_state_ != STOPPING) {
284    // If an out-of-order response is received, stop_callback_ may be invalid,
285    // and must not be invoked.
286    DLOG(ERROR) << "OnLoggingStoppedInRenderer invoked in state "
287                << logging_state_;
288    BadMessageReceived();
289    return;
290  }
291  logging_started_time_ = base::Time();
292  logging_state_ = STOPPED;
293  FireGenericDoneCallback(&stop_callback_, true, "");
294}
295
296void WebRtcLoggingHandlerHost::StartLoggingIfAllowed() {
297  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
298  if (!g_browser_process->webrtc_log_uploader()->ApplyForStartLogging()) {
299    logging_state_ = CLOSED;
300      FireGenericDoneCallback(
301          &start_callback_, false, "Cannot start, maybe the maximum number of "
302          "simultaneuos logs has been reached.");
303    return;
304  }
305  BrowserThread::PostTask(BrowserThread::IO, FROM_HERE, base::Bind(
306      &WebRtcLoggingHandlerHost::DoStartLogging, this));
307}
308
309void WebRtcLoggingHandlerHost::DoStartLogging() {
310  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
311
312  log_buffer_.reset(new unsigned char[kWebRtcLogSize]);
313  circular_buffer_.reset(
314    new PartialCircularBuffer(log_buffer_.get(),
315                              kWebRtcLogSize,
316                              kWebRtcLogSize / 2,
317                              false));
318
319  BrowserThread::PostTask(BrowserThread::FILE, FROM_HERE, base::Bind(
320      &WebRtcLoggingHandlerHost::LogInitialInfoOnFileThread, this));
321}
322
323void WebRtcLoggingHandlerHost::LogInitialInfoOnFileThread() {
324  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::FILE));
325
326  net::NetworkInterfaceList network_list;
327  net::GetNetworkList(&network_list,
328                      net::EXCLUDE_HOST_SCOPE_VIRTUAL_INTERFACES);
329
330  BrowserThread::PostTask(BrowserThread::IO, FROM_HERE, base::Bind(
331      &WebRtcLoggingHandlerHost::LogInitialInfoOnIOThread, this, network_list));
332}
333
334void WebRtcLoggingHandlerHost::LogInitialInfoOnIOThread(
335    const net::NetworkInterfaceList& network_list) {
336  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
337
338  // Log start time (current time). We don't use base/i18n/time_formatting.h
339  // here because we don't want the format of the current locale.
340  base::Time::Exploded now = {0};
341  base::Time::Now().LocalExplode(&now);
342  LogToCircularBuffer(base::StringPrintf(
343      "Start %d-%02d-%02d %02d:%02d:%02d", now.year, now.month,
344      now.day_of_month, now.hour, now.minute, now.second));
345
346  // Write metadata if received before logging started.
347  if (!meta_data_.empty()) {
348    std::string info;
349    FormatMetaDataAsLogMessage(meta_data_, &info);
350    LogToCircularBuffer(info);
351  }
352
353  // OS
354  LogToCircularBuffer(base::SysInfo::OperatingSystemName() + " " +
355                      base::SysInfo::OperatingSystemVersion() + " " +
356                      base::SysInfo::OperatingSystemArchitecture());
357#if defined(OS_LINUX)
358  LogToCircularBuffer("Linux distribution: " + base::GetLinuxDistro());
359#endif
360
361  // CPU
362  base::CPU cpu;
363  LogToCircularBuffer(
364      "Cpu: " + IntToString(cpu.family()) + "." + IntToString(cpu.model()) +
365      "." + IntToString(cpu.stepping()) + ", x" +
366      IntToString(base::SysInfo::NumberOfProcessors()) + ", " +
367      IntToString(base::SysInfo::AmountOfPhysicalMemoryMB()) + "MB");
368  std::string cpu_brand = cpu.cpu_brand();
369  // Workaround for crbug.com/249713.
370  // TODO(grunell): Remove workaround when bug is fixed.
371  size_t null_pos = cpu_brand.find('\0');
372  if (null_pos != std::string::npos)
373    cpu_brand.erase(null_pos);
374  LogToCircularBuffer("Cpu brand: " + cpu_brand);
375
376  // Computer model
377  std::string computer_model = "Not available";
378#if defined(OS_MACOSX)
379  computer_model = base::mac::GetModelIdentifier();
380#elif defined(OS_CHROMEOS)
381  chromeos::system::StatisticsProvider::GetInstance()->
382      GetMachineStatistic(chromeos::system::kHardwareClassKey, &computer_model);
383#endif
384  LogToCircularBuffer("Computer model: " + computer_model);
385
386  // GPU
387  gpu::GPUInfo gpu_info = content::GpuDataManager::GetInstance()->GetGPUInfo();
388  LogToCircularBuffer("Gpu: machine-model='" + gpu_info.machine_model +
389                      "', vendor-id=" + IntToString(gpu_info.gpu.vendor_id) +
390                      ", device-id=" + IntToString(gpu_info.gpu.device_id) +
391                      ", driver-vendor='" + gpu_info.driver_vendor +
392                      "', driver-version=" + gpu_info.driver_version);
393
394  // Network interfaces
395  LogToCircularBuffer("Discovered " + IntToString(network_list.size()) +
396                      " network interfaces:");
397  for (net::NetworkInterfaceList::const_iterator it = network_list.begin();
398       it != network_list.end(); ++it) {
399    LogToCircularBuffer("Name: " + it->friendly_name + ", Address: " +
400                        IPAddressToSensitiveString(it->address));
401  }
402
403  NotifyLoggingStarted();
404}
405
406void WebRtcLoggingHandlerHost::NotifyLoggingStarted() {
407  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
408  Send(new WebRtcLoggingMsg_StartLogging());
409  logging_started_time_ = base::Time::Now();
410  logging_state_ = STARTED;
411  FireGenericDoneCallback(&start_callback_, true, "");
412}
413
414void WebRtcLoggingHandlerHost::LogToCircularBuffer(const std::string& message) {
415  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
416  DCHECK(circular_buffer_.get());
417  circular_buffer_->Write(message.c_str(), message.length());
418  const char eol = '\n';
419  circular_buffer_->Write(&eol, 1);
420}
421
422base::FilePath WebRtcLoggingHandlerHost::GetLogDirectoryAndEnsureExists() {
423  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::FILE));
424  base::FilePath log_dir_path =
425      WebRtcLogList::GetWebRtcLogDirectoryForProfile(profile_->GetPath());
426  base::File::Error error;
427  if (!base::CreateDirectoryAndGetError(log_dir_path, &error)) {
428    DLOG(ERROR) << "Could not create WebRTC log directory, error: " << error;
429    return base::FilePath();
430  }
431  return log_dir_path;
432}
433
434void WebRtcLoggingHandlerHost::TriggerUploadLog(
435    const base::FilePath& log_directory) {
436  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
437  DCHECK(logging_state_ == STOPPED);
438
439  logging_state_ = UPLOADING;
440  WebRtcLogUploadDoneData upload_done_data;
441
442  upload_done_data.log_path = log_directory;
443  upload_done_data.callback = upload_callback_;
444  upload_done_data.host = this;
445  upload_callback_.Reset();
446
447  BrowserThread::PostTask(BrowserThread::FILE, FROM_HERE, base::Bind(
448      &WebRtcLogUploader::LoggingStoppedDoUpload,
449      base::Unretained(g_browser_process->webrtc_log_uploader()),
450      Passed(&log_buffer_),
451      kWebRtcLogSize,
452      meta_data_,
453      upload_done_data));
454
455  meta_data_.clear();
456  circular_buffer_.reset();
457}
458
459void WebRtcLoggingHandlerHost::FireGenericDoneCallback(
460    GenericDoneCallback* callback, bool success,
461    const std::string& error_message) {
462  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
463  DCHECK(!(*callback).is_null());
464  content::BrowserThread::PostTask(content::BrowserThread::UI, FROM_HERE,
465                                   base::Bind(*callback, success,
466                                              error_message));
467  (*callback).Reset();
468}
469