Bug 1434477 - Add extra logging to MediaManager's device enumeration path. r?padenot draft
authorBryce Van Dyk <bvandyk@mozilla.com>
Fri, 16 Mar 2018 15:09:55 -0400
changeset 770327 23dc7ef9ef562f20d4f803a07ff9654a832c988f
parent 769888 827c686c570935483c3ad8022aa92b9e005574c3
child 770328 1baea1fcba118664689e689dc69696b2d73c8ebd
push id103379
push userbvandyk@mozilla.com
push dateWed, 21 Mar 2018 00:12:14 +0000
reviewerspadenot
bugs1434477
milestone61.0a1
Bug 1434477 - Add extra logging to MediaManager's device enumeration path. r?padenot Add logging was added to help diagnose gUM failures and provide more log coverage of that code path. MozReview-Commit-ID: A76fjlUVpmn
dom/media/GraphDriver.cpp
dom/media/MediaManager.cpp
--- a/dom/media/GraphDriver.cpp
+++ b/dom/media/GraphDriver.cpp
@@ -488,16 +488,18 @@ AsyncCubebTask::Run()
 {
   MOZ_ASSERT(mDriver);
 
   switch(mOperation) {
     case AsyncCubebOperation::INIT: {
       LOG(LogLevel::Debug,
           ("AsyncCubebOperation::INIT driver=%p", mDriver.get()));
       if (!mDriver->Init()) {
+        LOG(LogLevel::Warning,
+            ("AsyncCubebOperation::INIT failed for driver=%p", mDriver.get()));
         return NS_ERROR_FAILURE;
       }
       mDriver->CompleteAudioContextOperations(mOperation);
       break;
     }
     case AsyncCubebOperation::SHUTDOWN: {
       LOG(LogLevel::Debug,
           ("AsyncCubebOperation::SHUTDOWN driver=%p", mDriver.get()));
--- a/dom/media/MediaManager.cpp
+++ b/dom/media/MediaManager.cpp
@@ -1175,16 +1175,17 @@ public:
     // DOMMediaStream::NotifyMediaStreamGraphShutdown is called.
     RefPtr<DOMMediaStream> mStream;
   };
 
   NS_IMETHOD
   Run() override
   {
     MOZ_ASSERT(NS_IsMainThread());
+    LOG(("GetUserMediaStreamRunnable::Run()"));
     nsGlobalWindowInner* globalWindow = nsGlobalWindowInner::GetInnerWindowWithId(mWindowID);
     nsPIDOMWindowInner* window = globalWindow ? globalWindow->AsInner() : nullptr;
 
     // We're on main-thread, and the windowlist can only
     // be invalidated from the main-thread (see OnNavigation)
     GetUserMediaWindowListener* listener =
       mManager->GetWindowListener(mWindowID);
     if (!listener || !window || !window->GetExtantDoc()) {
@@ -1426,24 +1427,28 @@ public:
     // because that can take a while.
     // Pass ownership of domStream through the lambda to the nested chrome
     // notification lambda to ensure it's kept alive until that lambda runs or is discarded.
     mSourceListener->InitializeAsync()->Then(
       GetMainThreadSerialEventTarget(), __func__,
       [manager = mManager, domStream, callback,
        windowListener = mWindowListener]()
       {
+        LOG(("GetUserMediaStreamRunnable::Run: starting success callback "
+             "following InitializeAsync()"));
         // Initiating and starting devices succeeded.
         // onTracksAvailableCallback must be added to domStream on main thread.
         domStream->OnTracksAvailable(callback->release());
         windowListener->ChromeAffectingStateChanged();
         manager->SendPendingGUMRequest();
       },[manager = mManager, windowID = mWindowID,
          onFailure = Move(mOnFailure)](const RefPtr<MediaMgrError>& error)
       {
+        LOG(("GetUserMediaStreamRunnable::Run: starting failure callback "
+             "following InitializeAsync()"));
         // Initiating and starting devices failed.
 
         // Only run if the window is still active for our window listener.
         if (!(manager->IsWindowStillActive(windowID))) {
           return;
         }
         // This is safe since we're on main-thread, and the windowlist can only
         // be invalidated from the main-thread (see OnNavigation)
@@ -1474,50 +1479,56 @@ private:
   ipc::PrincipalInfo mPrincipalInfo;
   RefPtr<PeerIdentity> mPeerIdentity;
   RefPtr<MediaManager> mManager; // get ref to this when creating the runnable
 };
 
 // Source getter returning full list
 
 static void
-GetSources(MediaEngine *engine,
+GetSources(MediaEngine *aEngine,
            uint64_t aWindowId,
            MediaSourceEnum aSrcType,
            nsTArray<RefPtr<MediaDevice>>& aResult,
-           const char* media_device_name = nullptr)
+           const char* aMediaDeviceName = nullptr)
 {
   MOZ_ASSERT(MediaManager::IsInMediaThread());
 
+  LOG(("%s: aEngine=%p, aWindowId=%" PRIu64 ", aSrcType=%" PRIu8 ", aMediaDeviceName=%s",
+       __func__, aEngine, aWindowId, static_cast<uint8_t>(aSrcType),
+       aMediaDeviceName ? aMediaDeviceName : "null"));
   nsTArray<RefPtr<MediaEngineSource>> sources;
-  engine->EnumerateDevices(aWindowId, aSrcType, &sources);
+  aEngine->EnumerateDevices(aWindowId, aSrcType, &sources);
 
   /*
    * We're allowing multiple tabs to access the same camera for parity
    * with Chrome.  See bug 811757 for some of the issues surrounding
    * this decision.  To disallow, we'd filter by IsAvailable() as we used
    * to.
    */
-  if (media_device_name && *media_device_name)  {
+  if (aMediaDeviceName && *aMediaDeviceName)  {
     for (auto& source : sources) {
       nsString deviceName = source->GetName();
-      if (deviceName.EqualsASCII(media_device_name)) {
+      if (deviceName.EqualsASCII(aMediaDeviceName)) {
         aResult.AppendElement(MakeRefPtr<MediaDevice>(
               source,
               source->GetName(),
               NS_ConvertUTF8toUTF16(source->GetUUID())));
+        LOG(("%s: found aMediaDeviceName=%s", __func__, aMediaDeviceName));
         break;
       }
     }
   } else {
     for (auto& source : sources) {
       aResult.AppendElement(MakeRefPtr<MediaDevice>(
             source,
             source->GetName(),
             NS_ConvertUTF8toUTF16(source->GetUUID())));
+      LOG(("%s: appending device=%s", __func__,
+           NS_ConvertUTF16toUTF8(source->GetName()).get()));
     }
   }
 }
 
 // TODO: Remove once upgraded to GCC 4.8+ on linux. Bogus error on static func:
 // error: 'this' was not captured for this lambda function
 
 static auto& MediaManager_ToJSArray = MediaManager::ToJSArray;
@@ -1653,16 +1664,17 @@ public:
 
   NS_IMETHOD
   Run() override
   {
     MOZ_ASSERT(!NS_IsMainThread());
     MOZ_ASSERT(mOnSuccess);
     MOZ_ASSERT(mOnFailure);
     MOZ_ASSERT(mDeviceChosen);
+    LOG(("GetUserMediaTask::Run()"));
 
     // Allocate a video or audio device and return a MediaStream via
     // a GetUserMediaStreamRunnable.
 
     nsresult rv;
     const char* errorMsg = nullptr;
     const char* badConstraint = nullptr;
 
@@ -2693,53 +2705,62 @@ MediaManager::GetUserMedia(nsPIDOMWindow
       (realDevicesRequested || Preferences::GetBool("media.navigator.permission.fake"));
 
   RefPtr<PledgeSourceSet> p = EnumerateDevicesImpl(windowID, videoType,
                                                    audioType, fake);
   RefPtr<MediaManager> self = this;
   p->Then([self, onSuccess, onFailure, windowID, c, windowListener,
            sourceListener, askPermission, prefs, isHTTPS, isHandlingUserInput,
            callID, principalInfo, isChrome, resistFingerprinting](SourceSet*& aDevices) mutable {
+    LOG(("GetUserMedia: post enumeration pledge success callback starting"));
     // grab result
     auto devices = MakeRefPtr<Refcountable<UniquePtr<SourceSet>>>(aDevices);
 
     // Ensure that our windowID is still good.
     if (!nsGlobalWindowInner::GetInnerWindowWithId(windowID)) {
+      LOG(("GetUserMedia: bad windowID found in post enumeration pledge "
+           " success callback! Bailing out!"));
       return;
     }
 
     // Apply any constraints. This modifies the passed-in list.
     RefPtr<PledgeChar> p2 = self->SelectSettings(c, isChrome, devices);
 
     p2->Then([self, onSuccess, onFailure, windowID, c,
               windowListener, sourceListener, askPermission, prefs, isHTTPS,
               isHandlingUserInput, callID, principalInfo, isChrome, devices,
               resistFingerprinting
              ](const char*& badConstraint) mutable {
+      LOG(("GetUserMedia: starting post enumeration pledge2 success "
+           "callback!"));
 
       // Ensure that the captured 'this' pointer and our windowID are still good.
       auto* globalWindow = nsGlobalWindowInner::GetInnerWindowWithId(windowID);
       RefPtr<nsPIDOMWindowInner> window = globalWindow ? globalWindow->AsInner()
                                                        : nullptr;
       if (!MediaManager::Exists() || !window) {
         return;
       }
 
       if (badConstraint) {
+        LOG(("GetUserMedia: bad constraint found in post enumeration pledge2 "
+             "success callback! Calling error handler!"));
         nsString constraint;
         constraint.AssignASCII(badConstraint);
         RefPtr<MediaStreamError> error =
             new MediaStreamError(window,
                                  NS_LITERAL_STRING("OverconstrainedError"),
                                  NS_LITERAL_STRING(""),
                                  constraint);
         onFailure->OnError(error);
         return;
       }
       if (!(*devices)->Length()) {
+        LOG(("GetUserMedia: no devices found in post enumeration pledge2 "
+             "success callback! Calling error handler!"));
         RefPtr<MediaStreamError> error =
             new MediaStreamError(
                 window,
                 // When privacy.resistFingerprinting = true, no available
                 // device implies content script is requesting a fake
                 // device, so report NotAllowedError.
                 resistFingerprinting ? NS_LITERAL_STRING("NotAllowedError")
                                      : NS_LITERAL_STRING("NotFoundError"));
@@ -2794,19 +2815,21 @@ MediaManager::GetUserMedia(nsPIDOMWindow
           obs->NotifyObservers(req, "getUserMedia:request", nullptr);
         }
       }
 
 #ifdef MOZ_WEBRTC
       EnableWebRtcLog();
 #endif
     }, [onFailure](MediaStreamError*& reason) mutable {
+      LOG(("GetUserMedia: post enumeration pledge2 failure callback called!"));
       onFailure->OnError(reason);
     });
   }, [onFailure](MediaStreamError*& reason) mutable {
+    LOG(("GetUserMedia: post enumeration pledge failure callback called!"));
     onFailure->OnError(reason);
   });
   return NS_OK;
 }
 
 /* static */ void
 MediaManager::AnonymizeDevices(SourceSet& aDevices, const nsACString& aOriginKey)
 {