webrtc_logging_handler_host.cc revision effb81e5f8246d0db0270817048dc992db66e9fb 
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, this, message));
223}
224
225void WebRtcLoggingHandlerHost::OnChannelClosing() {
226  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
227  if (logging_state_ == STARTED || logging_state_ == STOPPED) {
228    if (upload_log_on_render_close_) {
229      logging_state_ = STOPPED;
230      content::BrowserThread::PostTaskAndReplyWithResult(
231          content::BrowserThread::FILE,
232          FROM_HERE,
233          base::Bind(&WebRtcLoggingHandlerHost::GetLogDirectoryAndEnsureExists,
234                     this),
235          base::Bind(&WebRtcLoggingHandlerHost::TriggerUploadLog, this));
236    } else {
237      g_browser_process->webrtc_log_uploader()->LoggingStoppedDontUpload();
238    }
239  }
240  content::BrowserMessageFilter::OnChannelClosing();
241}
242
243void WebRtcLoggingHandlerHost::OnDestruct() const {
244  BrowserThread::DeleteOnIOThread::Destruct(this);
245}
246
247bool WebRtcLoggingHandlerHost::OnMessageReceived(const IPC::Message& message,
248                                                 bool* message_was_ok) {
249  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
250  bool handled = true;
251  IPC_BEGIN_MESSAGE_MAP_EX(WebRtcLoggingHandlerHost, message, *message_was_ok)
252    IPC_MESSAGE_HANDLER(WebRtcLoggingMsg_AddLogMessage, OnAddLogMessage)
253    IPC_MESSAGE_HANDLER(WebRtcLoggingMsg_LoggingStopped,
254                        OnLoggingStoppedInRenderer)
255    IPC_MESSAGE_UNHANDLED(handled = false)
256  IPC_END_MESSAGE_MAP_EX()
257
258  return handled;
259}
260
261void WebRtcLoggingHandlerHost::AddLogMessageFromBrowser(
262    const std::string& message) {
263  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
264  if (logging_state_ == STARTED)
265    LogToCircularBuffer(message);
266}
267
268void WebRtcLoggingHandlerHost::OnAddLogMessage(const std::string& message) {
269  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
270  if (logging_state_ == STARTED || logging_state_ == STOPPING)
271    LogToCircularBuffer(message);
272}
273
274void WebRtcLoggingHandlerHost::OnLoggingStoppedInRenderer() {
275  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
276  if (logging_state_ != STOPPING) {
277    // If an out-of-order response is received, stop_callback_ may be invalid,
278    // and must not be invoked.
279    DLOG(ERROR) << "OnLoggingStoppedInRenderer invoked in state "
280                << logging_state_;
281    BadMessageReceived();
282    return;
283  }
284  logging_state_ = STOPPED;
285  FireGenericDoneCallback(&stop_callback_, true, "");
286}
287
288void WebRtcLoggingHandlerHost::StartLoggingIfAllowed() {
289  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
290  if (!g_browser_process->webrtc_log_uploader()->ApplyForStartLogging()) {
291    logging_state_ = CLOSED;
292      FireGenericDoneCallback(
293          &start_callback_, false, "Cannot start, maybe the maximum number of "
294          "simultaneuos logs has been reached.");
295    return;
296  }
297  BrowserThread::PostTask(BrowserThread::IO, FROM_HERE, base::Bind(
298      &WebRtcLoggingHandlerHost::DoStartLogging, this));
299}
300
301void WebRtcLoggingHandlerHost::DoStartLogging() {
302  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
303
304  log_buffer_.reset(new unsigned char[kWebRtcLogSize]);
305  circular_buffer_.reset(
306    new PartialCircularBuffer(log_buffer_.get(),
307                              kWebRtcLogSize,
308                              kWebRtcLogSize / 2,
309                              false));
310
311  BrowserThread::PostTask(BrowserThread::FILE, FROM_HERE, base::Bind(
312      &WebRtcLoggingHandlerHost::LogInitialInfoOnFileThread, this));
313}
314
315void WebRtcLoggingHandlerHost::LogInitialInfoOnFileThread() {
316  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::FILE));
317
318  net::NetworkInterfaceList network_list;
319  net::GetNetworkList(&network_list,
320                      net::EXCLUDE_HOST_SCOPE_VIRTUAL_INTERFACES);
321
322  BrowserThread::PostTask(BrowserThread::IO, FROM_HERE, base::Bind(
323      &WebRtcLoggingHandlerHost::LogInitialInfoOnIOThread, this, network_list));
324}
325
326void WebRtcLoggingHandlerHost::LogInitialInfoOnIOThread(
327    const net::NetworkInterfaceList& network_list) {
328  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
329
330  // Log start time (current time). We don't use base/i18n/time_formatting.h
331  // here because we don't want the format of the current locale.
332  base::Time::Exploded now = {0};
333  base::Time::Now().LocalExplode(&now);
334  LogToCircularBuffer(base::StringPrintf(
335      "Start %d-%02d-%02d %02d:%02d:%02d", now.year, now.month,
336      now.day_of_month, now.hour, now.minute, now.second));
337
338  // Write metadata if received before logging started.
339  if (!meta_data_.empty()) {
340    std::string info;
341    FormatMetaDataAsLogMessage(meta_data_, &info);
342    LogToCircularBuffer(info);
343  }
344
345  // OS
346  LogToCircularBuffer(base::SysInfo::OperatingSystemName() + " " +
347                      base::SysInfo::OperatingSystemVersion() + " " +
348                      base::SysInfo::OperatingSystemArchitecture());
349#if defined(OS_LINUX)
350  LogToCircularBuffer("Linux distribution: " + base::GetLinuxDistro());
351#endif
352
353  // CPU
354  base::CPU cpu;
355  LogToCircularBuffer(
356      "Cpu: " + IntToString(cpu.family()) + "." + IntToString(cpu.model()) +
357      "." + IntToString(cpu.stepping()) + ", x" +
358      IntToString(base::SysInfo::NumberOfProcessors()) + ", " +
359      IntToString(base::SysInfo::AmountOfPhysicalMemoryMB()) + "MB");
360  std::string cpu_brand = cpu.cpu_brand();
361  // Workaround for crbug.com/249713.
362  // TODO(grunell): Remove workaround when bug is fixed.
363  size_t null_pos = cpu_brand.find('\0');
364  if (null_pos != std::string::npos)
365    cpu_brand.erase(null_pos);
366  LogToCircularBuffer("Cpu brand: " + cpu_brand);
367
368  // Computer model
369  std::string computer_model = "Not available";
370#if defined(OS_MACOSX)
371  computer_model = base::mac::GetModelIdentifier();
372#elif defined(OS_CHROMEOS)
373  chromeos::system::StatisticsProvider::GetInstance()->
374      GetMachineStatistic(chromeos::system::kHardwareClassKey, &computer_model);
375#endif
376  LogToCircularBuffer("Computer model: " + computer_model);
377
378  // GPU
379  gpu::GPUInfo gpu_info = content::GpuDataManager::GetInstance()->GetGPUInfo();
380  LogToCircularBuffer("Gpu: machine-model='" + gpu_info.machine_model +
381                      "', vendor-id=" + IntToString(gpu_info.gpu.vendor_id) +
382                      ", device-id=" + IntToString(gpu_info.gpu.device_id) +
383                      ", driver-vendor='" + gpu_info.driver_vendor +
384                      "', driver-version=" + gpu_info.driver_version);
385
386  // Network interfaces
387  LogToCircularBuffer("Discovered " + IntToString(network_list.size()) +
388                      " network interfaces:");
389  for (net::NetworkInterfaceList::const_iterator it = network_list.begin();
390       it != network_list.end(); ++it) {
391    LogToCircularBuffer("Name: " + it->friendly_name + ", Address: " +
392                        IPAddressToSensitiveString(it->address));
393  }
394
395  NotifyLoggingStarted();
396}
397
398void WebRtcLoggingHandlerHost::NotifyLoggingStarted() {
399  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
400  Send(new WebRtcLoggingMsg_StartLogging());
401  logging_state_ = STARTED;
402  FireGenericDoneCallback(&start_callback_, true, "");
403}
404
405void WebRtcLoggingHandlerHost::LogToCircularBuffer(const std::string& message) {
406  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
407  DCHECK(circular_buffer_.get());
408  circular_buffer_->Write(message.c_str(), message.length());
409  const char eol = '\n';
410  circular_buffer_->Write(&eol, 1);
411}
412
413base::FilePath WebRtcLoggingHandlerHost::GetLogDirectoryAndEnsureExists() {
414  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::FILE));
415  base::FilePath log_dir_path =
416      WebRtcLogList::GetWebRtcLogDirectoryForProfile(profile_->GetPath());
417  base::File::Error error;
418  if (!base::CreateDirectoryAndGetError(log_dir_path, &error)) {
419    DLOG(ERROR) << "Could not create WebRTC log directory, error: " << error;
420    return base::FilePath();
421  }
422  return log_dir_path;
423}
424
425void WebRtcLoggingHandlerHost::TriggerUploadLog(
426    const base::FilePath& log_directory) {
427  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
428  DCHECK(logging_state_ == STOPPED);
429
430  logging_state_ = UPLOADING;
431  WebRtcLogUploadDoneData upload_done_data;
432
433  upload_done_data.log_path = log_directory;
434  upload_done_data.callback = upload_callback_;
435  upload_done_data.host = this;
436  upload_callback_.Reset();
437
438  BrowserThread::PostTask(BrowserThread::FILE, FROM_HERE, base::Bind(
439      &WebRtcLogUploader::LoggingStoppedDoUpload,
440      base::Unretained(g_browser_process->webrtc_log_uploader()),
441      Passed(&log_buffer_),
442      kWebRtcLogSize,
443      meta_data_,
444      upload_done_data));
445
446  meta_data_.clear();
447  circular_buffer_.reset();
448}
449
450void WebRtcLoggingHandlerHost::FireGenericDoneCallback(
451    GenericDoneCallback* callback, bool success,
452    const std::string& error_message) {
453  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
454  DCHECK(!(*callback).is_null());
455  content::BrowserThread::PostTask(content::BrowserThread::UI, FROM_HERE,
456                                   base::Bind(*callback, success,
457                                              error_message));
458  (*callback).Reset();
459}
460