1 // Copyright 2016 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/webrtc_text_log_handler.h"
6 
7 #include <map>
8 #include <string>
9 #include <utility>
10 #include <vector>
11 
12 #include "base/bind.h"
13 #include "base/check_op.h"
14 #include "base/cpu.h"
15 #include "base/feature_list.h"
16 #include "base/metrics/histogram_functions.h"
17 #include "base/notreached.h"
18 #include "base/strings/strcat.h"
19 #include "base/strings/string_number_conversions.h"
20 #include "base/strings/stringprintf.h"
21 #include "base/system/sys_info.h"
22 #include "base/time/time.h"
23 #include "build/build_config.h"
24 #include "chrome/browser/media/audio_service_util.h"
25 #include "chrome/common/channel_info.h"
26 #include "chrome/common/media/webrtc_logging.mojom.h"
27 #include "components/version_info/version_info.h"
28 #include "content/public/browser/browser_task_traits.h"
29 #include "content/public/browser/browser_thread.h"
30 #include "content/public/browser/gpu_data_manager.h"
31 #include "content/public/browser/network_service_instance.h"
32 #include "content/public/browser/render_process_host.h"
33 #include "content/public/browser/webrtc_log.h"
34 #include "content/public/common/content_features.h"
35 #include "gpu/config/gpu_info.h"
36 #include "media/audio/audio_manager.h"
37 #include "media/webrtc/webrtc_switches.h"
38 #include "net/base/ip_address.h"
39 #include "net/base/network_change_notifier.h"
40 #include "net/base/network_interfaces.h"
41 #include "services/network/public/mojom/network_service.mojom.h"
42 
43 #if defined(OS_LINUX) || defined(OS_CHROMEOS)
44 #include "base/linux_util.h"
45 #include "base/task/thread_pool.h"
46 #endif
47 
48 #if defined(OS_MAC)
49 #include "base/mac/mac_util.h"
50 #endif
51 
52 #if defined(OS_CHROMEOS)
53 #include "chromeos/system/statistics_provider.h"
54 #endif
55 
56 using base::NumberToString;
57 
58 namespace {
59 
ForwardMessageViaTaskRunner(scoped_refptr<base::SequencedTaskRunner> task_runner,base::RepeatingCallback<void (const std::string &)> callback,const std::string & message)60 void ForwardMessageViaTaskRunner(
61     scoped_refptr<base::SequencedTaskRunner> task_runner,
62     base::RepeatingCallback<void(const std::string&)> callback,
63     const std::string& message) {
64   task_runner->PostTask(FROM_HERE,
65                         base::BindOnce(std::move(callback), message));
66 }
67 
Format(const std::string & message,base::Time timestamp,base::Time start_time)68 std::string Format(const std::string& message,
69                    base::Time timestamp,
70                    base::Time start_time) {
71   int32_t interval_ms =
72       static_cast<int32_t>((timestamp - start_time).InMilliseconds());
73   return base::StringPrintf("[%03d:%03d] %s", interval_ms / 1000,
74                             interval_ms % 1000, message.c_str());
75 }
76 
FormatMetaDataAsLogMessage(const WebRtcLogMetaDataMap & meta_data)77 std::string FormatMetaDataAsLogMessage(const WebRtcLogMetaDataMap& meta_data) {
78   std::string message;
79   for (auto& kv : meta_data) {
80     message += kv.first + ": " + kv.second + '\n';
81   }
82   // Remove last '\n'.
83   if (!message.empty())
84     message.erase(message.size() - 1, 1);  // TODO(terelius): Use pop_back()
85   return message;
86 }
87 
88 // For privacy reasons when logging IP addresses. The returned "sensitive
89 // string" is for release builds a string with the end stripped away. Last
90 // octet for IPv4 and last 80 bits (5 groups) for IPv6. String will be
91 // "1.2.3.x" and "1.2.3::" respectively. For debug builds, the string is
92 // not stripped.
IPAddressToSensitiveString(const net::IPAddress & address)93 std::string IPAddressToSensitiveString(const net::IPAddress& address) {
94 #if defined(NDEBUG)
95   std::string sensitive_address;
96   switch (address.size()) {
97     case net::IPAddress::kIPv4AddressSize: {
98       sensitive_address = address.ToString();
99       size_t find_pos = sensitive_address.rfind('.');
100       if (find_pos == std::string::npos)
101         return std::string();
102       sensitive_address.resize(find_pos);
103       sensitive_address += ".x";
104       break;
105     }
106     case net::IPAddress::kIPv6AddressSize: {
107       // TODO(grunell): Create a string of format "1:2:3:x:x:x:x:x" to clarify
108       // that the end has been stripped out.
109       net::IPAddressBytes stripped = address.bytes();
110       std::fill(stripped.begin() + 6, stripped.end(), 0);
111       sensitive_address = net::IPAddress(stripped).ToString();
112       break;
113     }
114     default: { break; }
115   }
116   return sensitive_address;
117 #else
118   return address.ToString();
119 #endif
120 }
121 
122 }  // namespace
123 
WebRtcTextLogHandler(int render_process_id)124 WebRtcTextLogHandler::WebRtcTextLogHandler(int render_process_id)
125     : render_process_id_(render_process_id), logging_state_(CLOSED) {}
126 
~WebRtcTextLogHandler()127 WebRtcTextLogHandler::~WebRtcTextLogHandler() {
128   // If the log isn't closed that means we haven't decremented the log count
129   // in the LogUploader.
130   DCHECK(logging_state_ == CLOSED || channel_is_closing_);
131   DCHECK(!log_buffer_);
132 }
133 
GetState() const134 WebRtcTextLogHandler::LoggingState WebRtcTextLogHandler::GetState() const {
135   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
136   return logging_state_;
137 }
138 
GetChannelIsClosing() const139 bool WebRtcTextLogHandler::GetChannelIsClosing() const {
140   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
141   return channel_is_closing_;
142 }
143 
SetMetaData(std::unique_ptr<WebRtcLogMetaDataMap> meta_data,GenericDoneCallback callback)144 void WebRtcTextLogHandler::SetMetaData(
145     std::unique_ptr<WebRtcLogMetaDataMap> meta_data,
146     GenericDoneCallback callback) {
147   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
148   DCHECK(!callback.is_null());
149 
150   if (channel_is_closing_) {
151     FireGenericDoneCallback(std::move(callback), false,
152                             "The renderer is closing.");
153     return;
154   }
155 
156   if (logging_state_ != CLOSED && logging_state_ != STARTED) {
157     FireGenericDoneCallback(std::move(callback), false,
158                             "Meta data must be set before stop or upload.");
159     return;
160   }
161 
162   if (logging_state_ == LoggingState::STARTED) {
163     std::string meta_data_message = FormatMetaDataAsLogMessage(*meta_data);
164     LogToCircularBuffer(meta_data_message);
165   }
166 
167   if (!meta_data_) {
168     // If no meta data has been set previously, set it now.
169     meta_data_ = std::move(meta_data);
170   } else if (meta_data) {
171     // If there is existing meta data, update it and any new fields. The meta
172     // data is kept around to be uploaded separately from the log.
173     for (const auto& it : *meta_data)
174       (*meta_data_)[it.first] = it.second;
175   }
176 
177   FireGenericDoneCallback(std::move(callback), true, "");
178 }
179 
StartLogging(WebRtcLogUploader * log_uploader,GenericDoneCallback callback)180 bool WebRtcTextLogHandler::StartLogging(WebRtcLogUploader* log_uploader,
181                                         GenericDoneCallback callback) {
182   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
183   DCHECK(!callback.is_null());
184 
185   if (channel_is_closing_) {
186     FireGenericDoneCallback(std::move(callback), false,
187                             "The renderer is closing.");
188     return false;
189   }
190 
191   if (logging_state_ != CLOSED) {
192     FireGenericDoneCallback(std::move(callback), false,
193                             "A log is already open.");
194     return false;
195   }
196 
197   if (!log_uploader->ApplyForStartLogging()) {
198     FireGenericDoneCallback(std::move(callback), false,
199                             "Cannot start, maybe the maximum number of "
200                             "simultaneuos logs has been reached.");
201     return false;
202   }
203 
204   logging_state_ = STARTING;
205 
206   DCHECK(!log_buffer_);
207   log_buffer_.reset(new WebRtcLogBuffer());
208   if (!meta_data_)
209     meta_data_.reset(new WebRtcLogMetaDataMap());
210 
211   content::GetNetworkService()->GetNetworkList(
212       net::EXCLUDE_HOST_SCOPE_VIRTUAL_INTERFACES,
213       base::BindOnce(&WebRtcTextLogHandler::OnGetNetworkInterfaceList,
214                      weak_factory_.GetWeakPtr(), std::move(callback)));
215   return true;
216 }
217 
StartDone(GenericDoneCallback callback)218 void WebRtcTextLogHandler::StartDone(GenericDoneCallback callback) {
219   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
220   DCHECK(!callback.is_null());
221 
222   if (channel_is_closing_) {
223     FireGenericDoneCallback(std::move(callback), false,
224                             "Failed to start log. Renderer is closing.");
225     return;
226   }
227 
228   DCHECK_EQ(STARTING, logging_state_);
229 
230   base::UmaHistogramSparse("WebRtcTextLogging.Start", web_app_id_);
231 
232   logging_started_time_ = base::Time::Now();
233   logging_state_ = STARTED;
234   FireGenericDoneCallback(std::move(callback), true, "");
235 }
236 
StopLogging(GenericDoneCallback callback)237 bool WebRtcTextLogHandler::StopLogging(GenericDoneCallback callback) {
238   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
239   DCHECK(!callback.is_null());
240 
241   if (channel_is_closing_) {
242     FireGenericDoneCallback(std::move(callback), false,
243                             "Can't stop log. Renderer is closing.");
244     return false;
245   }
246 
247   if (logging_state_ != STARTED) {
248     FireGenericDoneCallback(std::move(callback), false, "Logging not started.");
249     return false;
250   }
251 
252   stop_callback_ = std::move(callback);
253   logging_state_ = STOPPING;
254 
255   content::GetIOThreadTaskRunner({})->PostTask(
256       FROM_HERE, base::BindOnce(&content::WebRtcLog::ClearLogMessageCallback,
257                                 render_process_id_));
258   return true;
259 }
260 
StopDone()261 void WebRtcTextLogHandler::StopDone() {
262   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
263   DCHECK(stop_callback_);
264 
265   if (channel_is_closing_) {
266     FireGenericDoneCallback(std::move(stop_callback_), false,
267                             "Failed to stop log. Renderer is closing.");
268     return;
269   }
270 
271   // If we aren't in STOPPING state, then there is a bug in the caller, since
272   // it is responsible for checking the state before making the call. If we do
273   // enter here in a bad state, then we can't use the stop_callback_ or we
274   // might fire the same callback multiple times.
275   DCHECK_EQ(STOPPING, logging_state_);
276   if (logging_state_ == STOPPING) {
277     logging_started_time_ = base::Time();
278     logging_state_ = STOPPED;
279     FireGenericDoneCallback(std::move(stop_callback_), true, "");
280   }
281 }
282 
ChannelClosing()283 void WebRtcTextLogHandler::ChannelClosing() {
284   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
285   if (logging_state_ == STARTING || logging_state_ == STARTED) {
286     content::GetIOThreadTaskRunner({})->PostTask(
287         FROM_HERE, base::BindOnce(&content::WebRtcLog::ClearLogMessageCallback,
288                                   render_process_id_));
289   }
290   channel_is_closing_ = true;
291 }
292 
DiscardLog()293 void WebRtcTextLogHandler::DiscardLog() {
294   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
295   DCHECK(logging_state_ == STOPPED ||
296          (channel_is_closing_ && logging_state_ != CLOSED));
297 
298   base::UmaHistogramSparse("WebRtcTextLogging.Discard", web_app_id_);
299 
300   log_buffer_.reset();
301   meta_data_.reset();
302   logging_state_ = LoggingState::CLOSED;
303 }
304 
ReleaseLog(std::unique_ptr<WebRtcLogBuffer> * log_buffer,std::unique_ptr<WebRtcLogMetaDataMap> * meta_data)305 void WebRtcTextLogHandler::ReleaseLog(
306     std::unique_ptr<WebRtcLogBuffer>* log_buffer,
307     std::unique_ptr<WebRtcLogMetaDataMap>* meta_data) {
308   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
309   DCHECK(logging_state_ == STOPPED ||
310          (channel_is_closing_ && logging_state_ != CLOSED));
311   DCHECK(log_buffer_);
312   DCHECK(meta_data_);
313 
314   // Checking log_buffer_ here due to seeing some crashes out in the wild.
315   // See crbug/699960 for more details.
316   // TODO(crbug/807547): Remove if condition.
317   if (log_buffer_) {
318     log_buffer_->SetComplete();
319     *log_buffer = std::move(log_buffer_);
320   }
321 
322   if (meta_data_)
323     *meta_data = std::move(meta_data_);
324 
325   logging_state_ = LoggingState::CLOSED;
326 }
327 
LogToCircularBuffer(const std::string & message)328 void WebRtcTextLogHandler::LogToCircularBuffer(const std::string& message) {
329   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
330   DCHECK_NE(logging_state_, CLOSED);
331   if (log_buffer_) {
332     log_buffer_->Log(message);
333   }
334 }
335 
LogMessage(const std::string & message)336 void WebRtcTextLogHandler::LogMessage(const std::string& message) {
337   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
338   if (logging_state_ == STARTED && !channel_is_closing_) {
339     LogToCircularBuffer(
340         Format(message, base::Time::Now(), logging_started_time_));
341   }
342 }
343 
LogWebRtcLoggingMessage(const chrome::mojom::WebRtcLoggingMessage * message)344 void WebRtcTextLogHandler::LogWebRtcLoggingMessage(
345     const chrome::mojom::WebRtcLoggingMessage* message) {
346   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
347   LogToCircularBuffer(
348       Format(message->data, message->timestamp, logging_started_time_));
349 }
350 
ExpectLoggingStateStopped(GenericDoneCallback * callback)351 bool WebRtcTextLogHandler::ExpectLoggingStateStopped(
352     GenericDoneCallback* callback) {
353   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
354   if (logging_state_ != STOPPED) {
355     FireGenericDoneCallback(std::move(*callback), false,
356                             "Logging not stopped or no log open.");
357     return false;
358   }
359   return true;
360 }
361 
FireGenericDoneCallback(GenericDoneCallback callback,bool success,const std::string & error_message)362 void WebRtcTextLogHandler::FireGenericDoneCallback(
363     GenericDoneCallback callback,
364     bool success,
365     const std::string& error_message) {
366   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
367   DCHECK(!callback.is_null());
368 
369   if (error_message.empty()) {
370     DCHECK(success);
371     base::SequencedTaskRunnerHandle::Get()->PostTask(
372         FROM_HERE, base::BindOnce(std::move(callback), success, error_message));
373     return;
374   }
375 
376   DCHECK(!success);
377 
378   // Add current logging state to error message.
379   auto state_string = [&] {
380     switch (logging_state_) {
381       case LoggingState::CLOSED:
382         return "closed";
383       case LoggingState::STARTING:
384         return "starting";
385       case LoggingState::STARTED:
386         return "started";
387       case LoggingState::STOPPING:
388         return "stopping";
389       case LoggingState::STOPPED:
390         return "stopped";
391     }
392     NOTREACHED();
393     return "";
394   };
395 
396   std::string error_message_with_state =
397       base::StrCat({error_message, ". State=", state_string(), ". Channel is ",
398                     channel_is_closing_ ? "" : "not ", "closing."});
399 
400   base::SequencedTaskRunnerHandle::Get()->PostTask(
401       FROM_HERE,
402       base::BindOnce(std::move(callback), success, error_message_with_state));
403 }
404 
SetWebAppId(int web_app_id)405 void WebRtcTextLogHandler::SetWebAppId(int web_app_id) {
406   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
407   web_app_id_ = web_app_id;
408 }
409 
OnGetNetworkInterfaceList(GenericDoneCallback callback,const base::Optional<net::NetworkInterfaceList> & networks)410 void WebRtcTextLogHandler::OnGetNetworkInterfaceList(
411     GenericDoneCallback callback,
412     const base::Optional<net::NetworkInterfaceList>& networks) {
413 #if defined(OS_LINUX) || defined(OS_CHROMEOS)
414   // Hop to a background thread to get the distro string, which can block.
415   base::ThreadPool::PostTaskAndReplyWithResult(
416       FROM_HERE, {base::MayBlock()}, base::BindOnce(&base::GetLinuxDistro),
417       base::BindOnce(&WebRtcTextLogHandler::OnGetNetworkInterfaceListFinish,
418                      weak_factory_.GetWeakPtr(), std::move(callback),
419                      networks));
420 #else
421   OnGetNetworkInterfaceListFinish(std::move(callback), networks, "");
422 #endif
423 }
424 
OnGetNetworkInterfaceListFinish(GenericDoneCallback callback,const base::Optional<net::NetworkInterfaceList> & networks,const std::string & linux_distro)425 void WebRtcTextLogHandler::OnGetNetworkInterfaceListFinish(
426     GenericDoneCallback callback,
427     const base::Optional<net::NetworkInterfaceList>& networks,
428     const std::string& linux_distro) {
429   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
430 
431   if (logging_state_ != STARTING || channel_is_closing_) {
432     FireGenericDoneCallback(std::move(callback), false, "Logging cancelled.");
433     return;
434   }
435 
436   // Log start time (current time). We don't use base/i18n/time_formatting.h
437   // here because we don't want the format of the current locale.
438   base::Time::Exploded now = {0};
439   base::Time::Now().LocalExplode(&now);
440   LogToCircularBuffer(base::StringPrintf("Start %d-%02d-%02d %02d:%02d:%02d",
441                                          now.year, now.month, now.day_of_month,
442                                          now.hour, now.minute, now.second));
443 
444   // Write metadata if received before logging started.
445   if (meta_data_ && !meta_data_->empty()) {
446     std::string info = FormatMetaDataAsLogMessage(*meta_data_);
447     LogToCircularBuffer(info);
448   }
449 
450   // Chrome version
451   LogToCircularBuffer("Chrome version: " + version_info::GetVersionNumber() +
452                       " " + chrome::GetChannelName());
453 
454   // OS
455   LogToCircularBuffer(base::SysInfo::OperatingSystemName() + " " +
456                       base::SysInfo::OperatingSystemVersion() + " " +
457                       base::SysInfo::OperatingSystemArchitecture());
458 #if defined(OS_LINUX) || defined(OS_CHROMEOS)
459   { LogToCircularBuffer("Linux distribution: " + linux_distro); }
460 #endif
461 
462   // CPU
463   base::CPU cpu;
464   LogToCircularBuffer(
465       "Cpu: " + NumberToString(cpu.family()) + "." +
466       NumberToString(cpu.model()) + "." + NumberToString(cpu.stepping()) +
467       ", x" + NumberToString(base::SysInfo::NumberOfProcessors()) + ", " +
468       NumberToString(base::SysInfo::AmountOfPhysicalMemoryMB()) + "MB");
469   LogToCircularBuffer("Cpu brand: " + cpu.cpu_brand());
470 
471   // Computer model
472   std::string computer_model = "Not available";
473 #if defined(OS_MAC)
474   computer_model = base::mac::GetModelIdentifier();
475 #elif defined(OS_CHROMEOS)
476   chromeos::system::StatisticsProvider::GetInstance()->GetMachineStatistic(
477       chromeos::system::kHardwareClassKey, &computer_model);
478 #endif
479   LogToCircularBuffer("Computer model: " + computer_model);
480 
481   // GPU
482   gpu::GPUInfo gpu_info = content::GpuDataManager::GetInstance()->GetGPUInfo();
483   const gpu::GPUInfo::GPUDevice& active_gpu = gpu_info.active_gpu();
484   LogToCircularBuffer(
485       "Gpu: machine-model-name=" + gpu_info.machine_model_name +
486       ", machine-model-version=" + gpu_info.machine_model_version +
487       ", vendor-id=" + base::NumberToString(active_gpu.vendor_id) +
488       ", device-id=" + base::NumberToString(active_gpu.device_id) +
489       ", driver-vendor=" + active_gpu.driver_vendor +
490       ", driver-version=" + active_gpu.driver_version);
491   LogToCircularBuffer("OpenGL: gl-vendor=" + gpu_info.gl_vendor +
492                       ", gl-renderer=" + gpu_info.gl_renderer +
493                       ", gl-version=" + gpu_info.gl_version);
494 
495   // AudioService features
496   auto enabled_or_disabled_feature_string = [](auto& feature) {
497     return base::FeatureList::IsEnabled(feature) ? "enabled" : "disabled";
498   };
499   auto enabled_or_disabled_bool_string = [](bool value) {
500     return value ? "enabled" : "disabled";
501   };
502   LogToCircularBuffer(base::StrCat(
503       {"AudioService: OutOfProcess=",
504        enabled_or_disabled_feature_string(features::kAudioServiceOutOfProcess),
505        ", LaunchOnStartup=",
506        enabled_or_disabled_feature_string(
507            features::kAudioServiceLaunchOnStartup),
508        ", Sandbox=",
509        enabled_or_disabled_bool_string(IsAudioServiceSandboxEnabled())}));
510 
511   // Audio manager
512   // On some platforms, this can vary depending on build flags and failure
513   // fallbacks. On Linux for example, we fallback on ALSA if PulseAudio fails to
514   // initialize. TODO(http://crbug/843202): access AudioManager name via Audio
515   // service interface.
516   media::AudioManager* audio_manager = media::AudioManager::Get();
517   LogToCircularBuffer(base::StringPrintf(
518       "Audio manager: %s",
519       audio_manager ? audio_manager->GetName() : "Out of process"));
520 
521   // Network interfaces
522   const net::NetworkInterfaceList empty_network_list;
523   const net::NetworkInterfaceList& network_list =
524       networks.has_value() ? *networks : empty_network_list;
525   LogToCircularBuffer("Discovered " +
526                       base::NumberToString(network_list.size()) +
527                       " network interfaces:");
528   for (const auto& network : network_list) {
529     LogToCircularBuffer(
530         "Name: " + network.friendly_name + ", Address: " +
531         IPAddressToSensitiveString(network.address) + ", Type: " +
532         net::NetworkChangeNotifier::ConnectionTypeToString(network.type));
533   }
534 
535   StartDone(std::move(callback));
536 
537   // After the above data has been written, tell the browser to enable logging.
538   // TODO(terelius): Once we have moved over to Mojo, we could tell the
539   // renderer to start logging here, but for the time being
540   // WebRtcLoggingHandlerHost::StartLogging will be responsible for sending
541   // that IPC message.
542 
543   // TODO(darin): Change SetLogMessageCallback to run on the UI thread.
544 
545   auto log_message_callback = base::BindRepeating(
546       &ForwardMessageViaTaskRunner, base::SequencedTaskRunnerHandle::Get(),
547       base::BindRepeating(&WebRtcTextLogHandler::LogMessage,
548                           weak_factory_.GetWeakPtr()));
549   content::GetIOThreadTaskRunner({})->PostTask(
550       FROM_HERE,
551       base::BindOnce(&content::WebRtcLog::SetLogMessageCallback,
552                      render_process_id_, std::move(log_message_callback)));
553 }
554