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