Implement browser-side logging to WebRtc log

content/browser/renderer_host/media/media_stream_manager.cc

 // Copyright (c) 2012 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 "content/browser/renderer_host/media/media_stream_manager.h"
 
 #include <list>
 #include <vector>
 
 #include "base/bind.h"
 #include "base/command_line.h"
 #include "base/compiler_specific.h"
 #include "base/logging.h"
 #include "base/rand_util.h"
 #include "base/run_loop.h"
 #include "base/threading/thread.h"
+#include "content/browser/browser_main_loop.h"
 #include "content/browser/renderer_host/media/audio_input_device_manager.h"
 #include "content/browser/renderer_host/media/device_request_message_filter.h"
 #include "content/browser/renderer_host/media/media_stream_requester.h"
 #include "content/browser/renderer_host/media/media_stream_ui_proxy.h"
 #include "content/browser/renderer_host/media/video_capture_manager.h"
 #include "content/browser/renderer_host/media/web_contents_capture_util.h"
+#include "content/browser/renderer_host/render_process_host_impl.h"
 #include "content/public/browser/browser_thread.h"
 #include "content/public/browser/content_browser_client.h"
 #include "content/public/browser/media_device_id.h"
 #include "content/public/browser/media_observer.h"
 #include "content/public/browser/media_request_state.h"
+#include "content/public/browser/render_process_host.h"
 #include "content/public/common/content_switches.h"
 #include "content/public/common/media_stream_request.h"
 #include "media/audio/audio_manager_base.h"
 #include "media/audio/audio_parameters.h"
 #include "media/base/channel_layout.h"
 #include "url/gurl.h"
 
 #if defined(OS_WIN)
 #include "base/win/scoped_com_initializer.h"
 #endif
 
+static void DoAddLogMessage(const std::string& message) {

[tommi (sloooow) - chröme, 2014/01/24 12:34:54]

I think //content prefers anonymous namespaces (even inside the content
namespace).  //media is a bit special in this way and that's the style you're
following here I think.

[vrk (LEFT CHROMIUM), 2014/01/25 00:50:21]

Done.

+  // Must be on the UI thread to access BrowserMainLoop.
+  DCHECK(content::BrowserThread::CurrentlyOn(content::BrowserThread::UI));
+  // May be null in tests.
+  // TODO(vrk): Handle this more elegantly by having native log messages become
+  // no-ops until MediaStreamManager is aware that a renderer process has
+  // started logging. crbug.com/333894
+  if (content::BrowserMainLoop::GetInstance()) {
+    content::BrowserMainLoop::GetInstance()->
+        media_stream_manager()->AddLogMessageOnUIThread(message);
+  }
+}
+
 namespace content {
 
 namespace {
 // Creates a random label used to identify requests.
 std::string RandomLabel() {
   // An earlier PeerConnection spec,
   // http://dev.w3.org/2011/webrtc/editor/webrtc.html, specified the
   // MediaStream::label alphabet as containing 36 characters from
   // range: U+0021, U+0023 to U+0027, U+002A to U+002B, U+002D to U+002E,
   // U+0030 to U+0039, U+0041 to U+005A, U+005E to U+007E.
@@ skipping 790 matching lines @@
        ++it) {
     if (content::DoesMediaDeviceIDMatchHMAC(rc, security_origin, source_id,
                                             it->device.id)) {
       *device_id = it->device.id;
       return true;
     }
   }
   return false;
 }
 
+void MediaStreamManager::LogDevicesToNativeLogs(
+    MediaStreamType stream_type,
+    const StreamDeviceInfoArray& devices) {
+  std::stringstream devices_msg;
+  devices_msg << "Devices found for stream type " << stream_type << ":"
+              << std::endl;
+  for (StreamDeviceInfoArray::const_iterator it = devices.begin();
+       it != devices.end(); ++it) {
+    devices_msg << "  " << it->device.name << " ("
+                << it->device.id << ")" << std::endl;

[no longer working on chromium, 2014/01/24 09:54:38]

btw, are you supposed to log the device_id? has the private concern been
addressed here?

[tommi (sloooow) - chröme, 2014/01/24 12:34:54]

Agreed. To be safe we should either skip logging the ID or log only the ID as
javascript will see it (origin specific).

[vrk (LEFT CHROMIUM), 2014/01/25 00:50:21]

Removed. (Fwiw I also sent a mail to kaichou@ with sample logs to get the
privacy OK.)

[vrk (LEFT CHROMIUM), 2014/01/25 00:50:21]

Done, just omitted.

+  }
+  if (devices.empty())

[no longer working on chromium, 2014/01/24 09:54:38]

nit, I think it is cleaner to do:
if (devices.empty()) {
  devices_msg << "No devices found.";
} else {
  for (StreamDeviceInfoArray::const_iterator it = devices.begin();
       it != devices.end(); ++it) {
    devices_msg << "  " << it->device.name << " (" << it->device.id << ")" <<
std::endl;
}

[vrk (LEFT CHROMIUM), 2014/01/25 00:50:21]

Done.

+    devices_msg << "No devices found.";
+
+  DVLOG(1) << devices_msg;
+  SendMessageToNativeLog(devices_msg.str());
+}
+
 void MediaStreamManager::ClearEnumerationCache(EnumerationCache* cache) {
   DCHECK_EQ(base::MessageLoop::current(), io_loop_);
   cache->valid = false;
 }
 
 bool MediaStreamManager::EnumerationRequired(EnumerationCache* cache,
                                              MediaStreamType stream_type) {
   DCHECK_EQ(base::MessageLoop::current(), io_loop_);
   if (stream_type == MEDIA_NO_SERVICE)
     return false;
@@ skipping 148 matching lines @@
     FinalizeRequestFailed(label, request);
     return;
   }
 
   if (!is_web_contents_capture && !is_screen_capture) {
     if (EnumerationRequired(&audio_enumeration_cache_, audio_type) ||
         EnumerationRequired(&video_enumeration_cache_, video_type)) {
       // Enumerate the devices if there is no valid device lists to be used.
       StartEnumeration(request);
       return;
+    } else {
+      // Cache is valid, so log the cached devices.

[no longer working on chromium, 2014/01/24 09:54:38]

are you sure you want to log the cache for each SetupRequest?
Note that SetupRequest is used by all the clients, including pepper, and I know
that they call OpenDevice() once a while to poll the device. If things are still
the case, you will log a lot here.

[no longer working on chromium, 2014/01/24 10:36:17]

Per pointed out that only media stream requests were logged in
AddLogMessageOnUIThread. But what I understand from the code is that you might
log the same request multiple times. Right?

[vrk (LEFT CHROMIUM), 2014/01/25 00:50:21]

Thanks for letting me know. I don't think there will be many situations in which
people are running native logging and Pepper at the same time, but added an if
statement to limit to MediaStream requests. This isn't a great solution, but I
think the real problem is that MediaStreamManager needs to be refactored. At the
very least, I don't think pepper code should be in this class. I added
crbug.com/337982 for this cleanup.

+      SendMessageToNativeLog("Using cached devices for request.");

[tommi (sloooow) - chröme, 2014/01/24 12:34:54]

Would it make sense to aggregate all these messages into a single message so
that they're guaranteed to stay intact inside the log?

+      LogDevicesToNativeLogs(audio_type, audio_enumeration_cache_.devices);
+      LogDevicesToNativeLogs(video_type, video_enumeration_cache_.devices);

[no longer working on chromium, 2014/01/24 09:54:38]

what do you log if the type is MEDIA_NO_SERVICE ?

[vrk (LEFT CHROMIUM), 2014/01/25 00:50:21]

See LogDevicesToNativeLogs - it would log the MEDIA_NO_SERVICE enum value and
"No devices found." I don't think that's the worst thing in the world, but I
added some logic to make it clearer.

     }
 
     if (!SetupDeviceCaptureRequest(request)) {
       FinalizeRequestFailed(label, request);
       return;
     }
   }
   PostRequestToUI(label, request);
 }
 
@@ skipping 369 matching lines @@
 
 void MediaStreamManager::Closed(MediaStreamType stream_type,
                                 int capture_session_id) {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
 }
 
 void MediaStreamManager::DevicesEnumerated(
     MediaStreamType stream_type, const StreamDeviceInfoArray& devices) {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
   DVLOG(1) << "DevicesEnumerated("
-           << ", {stream_type = " << stream_type <<  "})";
+           << "{stream_type = " << stream_type << "})" << std::endl;
+
+  SendMessageToNativeLog("New device enumeration result:");
+  LogDevicesToNativeLogs(stream_type, devices);
 
   // Only cache the device list when the device list has been changed.
   bool need_update_clients = false;
   EnumerationCache* cache =
       stream_type == MEDIA_DEVICE_AUDIO_CAPTURE ?
       &audio_enumeration_cache_ : &video_enumeration_cache_;
   if (!cache->valid ||
       devices.size() != cache->devices.size() ||
       !std::equal(devices.begin(), devices.end(), cache->devices.begin(),
                   StreamDeviceInfo::IsEqual)) {
@@ skipping 52 matching lines @@
         else
           PostRequestToUI(*it, request);
         break;
     }
   }
   label_list.clear();
   --active_enumeration_ref_count_[stream_type];
   DCHECK_GE(active_enumeration_ref_count_[stream_type], 0);
 }
 
+// static
+void MediaStreamManager::SendMessageToNativeLog(const std::string& message) {
+  BrowserThread::PostTask(
+      BrowserThread::UI, FROM_HERE,

[no longer working on chromium, 2014/01/24 09:54:38]

I have some concern on the thread safety here. Previously MediaStreamManager is
listening to a WillDestroyCurrentMessageLoop() message to clean up its resource
when the IO thread is going away, then MediaStreamManager will be deleted on UI
thread.
But this method will post a task on UI thread to MediaStreamManager itself, can
it happen that MediaStreamManager gets deleted before the task is executed? I
think this is at least theoretically possible and depending on how this method
is used.

I believe you need to use a weak pointer to invalidate all the tasks when IO
thread is going away.

[tommi (sloooow) - chröme, 2014/01/24 12:34:54]

Actually, this method is static and the task that gets posted isn't bound to a
MediaStreamManager pointer.  DoAddLogMessage will actually do the checking of
whether the manager instance is dead or alive, so I think this is OK from that
standpoint.

[vrk (LEFT CHROMIUM), 2014/01/25 00:50:21]

I believe so as well, so leaving as is.

+      base::Bind(::DoAddLogMessage, message));
+}
+
+void MediaStreamManager::AddLogMessageOnUIThread(const std::string& message) {
+  // Must be on the UI thread to access RenderProcessHost from process ID.
+  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
+
+  // Add logs for each pending request.
+  for (DeviceRequests::iterator it = requests_.begin(); it != requests_.end();
+       ++it) {
+    DeviceRequest* request = it->second;
+    // Log the message to all renderers that are requesting a MediaStream or

[perkj_chrome, 2014/01/24 09:15:10]

Can you expand the comment : that are requesting a MediaStream or have a
MediaStream running

[vrk (LEFT CHROMIUM), 2014/01/25 00:50:21]

Done.

+    // device enumeration.
+    if (request->request_type == MEDIA_GENERATE_STREAM ||
+        request->request_type == MEDIA_ENUMERATE_DEVICES) {

[perkj_chrome, 2014/01/24 09:15:10]

Fyi- MEDIA_ENUMERATE_DEVICES is called by flash for some reason every 10s or so.


I would recommend that you run flash in one tab and webrtc in another and look
at the logs to see that you are not spammed.

[vrk (LEFT CHROMIUM), 2014/01/25 00:50:21]

Pepper flash? I don't understand why MediaStreamManager deals with Pepper
requests at all. I created crbug.com/337982 in response to this.
 
I just removed the MEDIA_ENUMERATE_DEVICES if statement. We really only care
about MEDIA_GENERATE_STREAM.

+      content::RenderProcessHostImpl* render_process_host_impl =
+          static_cast<content::RenderProcessHostImpl*>(
+              content::RenderProcessHost::FromID(
+                  request->requesting_process_id));
+      if (render_process_host_impl)
+        render_process_host_impl->WebRtcLogMessage(message);
+    }
+  }
+}
+
 void MediaStreamManager::HandleAccessRequestResponse(
     const std::string& label,
     const MediaStreamDevices& devices) {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
   DVLOG(1) << "HandleAccessRequestResponse("
            << ", {label = " << label <<  "})";
 
   DeviceRequest* request = FindRequest(label);
   if (!request) {
     // The request has been canceled before the UI returned.
@@ skipping 215 matching lines @@
   }
 
   // Always do enumeration even though some enumeration is in progress,
   // because those enumeration commands could be sent before these devices
   // change.
   ++active_enumeration_ref_count_[stream_type];
   GetDeviceManager(stream_type)->EnumerateDevices(stream_type);
 }
 
 }  // namespace content