Bug 1439473 - Improve logging of HTMLMediaElement JS API calls. r=kamidphish draft
authorChris Pearce <cpearce@mozilla.com>
Thu, 15 Feb 2018 16:39:44 +1300
changeset 758240 153a68f27ec5c2b17c3c5a9e31d54b98ccc1a1ea
parent 758231 38d77ce42ec5f4edb0119ba2ccf03f53cd8cdb00
push id99998
push userbmo:cpearce@mozilla.com
push dateThu, 22 Feb 2018 02:48:35 +0000
reviewerskamidphish
bugs1439473
milestone60.0a1
Bug 1439473 - Improve logging of HTMLMediaElement JS API calls. r=kamidphish To make it easier to tell what HTMLMediaElement API functions sites' JS is calling, we should add more mozlogs. This will make it easier to figure out why things aren't playing. MozReview-Commit-ID: 9eVvkagGNgf
dom/html/HTMLMediaElement.cpp
--- a/dom/html/HTMLMediaElement.cpp
+++ b/dom/html/HTMLMediaElement.cpp
@@ -1944,24 +1944,53 @@ static bool HasSourceChildren(nsIContent
     if (child->IsHTMLElement(nsGkAtoms::source))
     {
       return true;
     }
   }
   return false;
 }
 
+static nsCString
+DocumentOrigin(nsIDocument* aDoc)
+{
+  if (!aDoc) {
+    return NS_LITERAL_CSTRING("null");
+  }
+  nsCOMPtr<nsIPrincipal> principal = aDoc->NodePrincipal();
+  if (!principal) {
+    return NS_LITERAL_CSTRING("null");
+  }
+  nsCString origin;
+  if (NS_FAILED(principal->GetOrigin(origin))) {
+    return NS_LITERAL_CSTRING("null");
+  }
+  return origin;
+}
+
 void
 HTMLMediaElement::Load()
 {
   LOG(LogLevel::Debug,
       ("%p Load() hasSrcAttrStream=%d hasSrcAttr=%d hasSourceChildren=%d "
-       "handlingInput=%d",
-       this, !!mSrcAttrStream, HasAttr(kNameSpaceID_None, nsGkAtoms::src),
-       HasSourceChildren(this), EventStateManager::IsHandlingUserInput()));
+       "handlingInput=%d hasAutoplayAttr=%d IsAllowedToPlay=%d "
+       "ownerDoc=%p (%s) ownerDocUserActivated=%d "
+       "muted=%d volume=%f",
+       this,
+       !!mSrcAttrStream,
+       HasAttr(kNameSpaceID_None, nsGkAtoms::src),
+       HasSourceChildren(this),
+       EventStateManager::IsHandlingUserInput(),
+       HasAttr(kNameSpaceID_None, nsGkAtoms::autoplay),
+       IsAllowedToPlay(),
+       OwnerDoc(),
+       DocumentOrigin(OwnerDoc()).get(),
+       OwnerDoc() ? OwnerDoc()->HasBeenUserActivated() : 0,
+       mMuted,
+       mVolume));
 
   if (mIsRunningLoadMethod) {
     return;
   }
 
   mIsDoingExplicitLoad = true;
   DoLoad();
 }
@@ -2652,16 +2681,17 @@ HTMLMediaElement::CurrentTime() const
   }
 
   return mDefaultPlaybackStartPosition;
 }
 
 void
 HTMLMediaElement::FastSeek(double aTime, ErrorResult& aRv)
 {
+  LOG(LogLevel::Debug, ("%p FastSeek(%f) called by JS", this, aTime));
   LOG(LogLevel::Debug, ("Reporting telemetry VIDEO_FASTSEEK_USED"));
   Telemetry::Accumulate(Telemetry::VIDEO_FASTSEEK_USED, 1);
   RefPtr<Promise> tobeDropped = Seek(aTime, SeekTarget::PrevSyncPoint, aRv);
 }
 
 already_AddRefed<Promise>
 HTMLMediaElement::SeekToNextFrame(ErrorResult& aRv)
 {
@@ -2684,16 +2714,18 @@ HTMLMediaElement::SeekToNextFrame(ErrorR
   }
 
   return Seek(CurrentTime(), SeekTarget::NextFrame, aRv);
 }
 
 void
 HTMLMediaElement::SetCurrentTime(double aCurrentTime, ErrorResult& aRv)
 {
+  LOG(LogLevel::Debug,
+      ("%p SetCurrentTime(%f) called by JS", this, aCurrentTime));
   RefPtr<Promise> tobeDropped = Seek(aCurrentTime, SeekTarget::Accurate, aRv);
 }
 
 /**
  * Check if aValue is inside a range of aRanges, and if so sets aIsInRanges
  * to true and put the range index in aIntervalIndex. If aValue is not
  * inside a range, aIsInRanges is set to false, and aIntervalIndex
  * is set to the index of the range which ends immediately before aValue
@@ -2922,16 +2954,17 @@ HTMLMediaElement::Played()
 
   ranges->Normalize();
   return ranges.forget();
 }
 
 void
 HTMLMediaElement::Pause(ErrorResult& aRv)
 {
+  LOG(LogLevel::Debug, ("%p Pause() called by JS", this));
   if (mNetworkState == NETWORK_EMPTY) {
     LOG(LogLevel::Debug, ("Loading due to Pause()"));
     DoLoad();
   } else if (mDecoder) {
     mDecoder->Pause();
   }
 
   bool oldPaused = mPaused;
@@ -2949,16 +2982,18 @@ HTMLMediaElement::Pause(ErrorResult& aRv
     DispatchAsyncEvent(NS_LITERAL_STRING("pause"));
     AsyncRejectPendingPlayPromises(NS_ERROR_DOM_MEDIA_ABORT_ERR);
   }
 }
 
 void
 HTMLMediaElement::SetVolume(double aVolume, ErrorResult& aRv)
 {
+  LOG(LogLevel::Debug, ("%p SetVolume(%f) called by JS", this, aVolume));
+
   if (aVolume < 0.0 || aVolume > 1.0) {
     aRv.Throw(NS_ERROR_DOM_INDEX_SIZE_ERR);
     return;
   }
 
   if (aVolume == mVolume)
     return;
 
@@ -3031,16 +3066,17 @@ HTMLMediaElement::SetVolumeInternal()
 
   NotifyAudioPlaybackChanged(
     AudioChannelService::AudibleChangedReasons::eVolumeChanged);
 }
 
 void
 HTMLMediaElement::SetMuted(bool aMuted)
 {
+  LOG(LogLevel::Debug, ("%p SetMuted(%d) called by JS", this, aMuted));
   if (aMuted == Muted()) {
     return;
   }
 
   if (aMuted) {
     SetMutedInternal(mMuted | MUTED_BY_CONTENT);
   } else {
     SetMutedInternal(mMuted & ~MUTED_BY_CONTENT);
@@ -3976,28 +4012,32 @@ void
 HTMLMediaElement::NotifyXPCOMShutdown()
 {
   ShutdownDecoder();
 }
 
 already_AddRefed<Promise>
 HTMLMediaElement::Play(ErrorResult& aRv)
 {
+  LOG(LogLevel::Debug, ("%p Play() called by JS", this));
+
   if (mAudioChannelWrapper && mAudioChannelWrapper->IsPlaybackBlocked()) {
     MaybeDoLoad();
 
     // A blocked media element will be resumed later, so we return a pending
     // promise which might be resolved/rejected depends on the result of
     // resuming the blocked media element.
     RefPtr<Promise> promise = CreateDOMPromise(aRv);
 
     if (NS_WARN_IF(aRv.Failed())) {
       return nullptr;
     }
 
+    LOG(LogLevel::Debug, ("%p Play() call delayed by AudioChannelAgent", this));
+
     mPendingPlayPromises.AppendElement(promise);
     return promise.forget();
   }
 
   RefPtr<Promise> promise = PlayInternal(aRv);
 
   UpdateCustomPolicyAfterPlayed();
 
@@ -4013,25 +4053,29 @@ HTMLMediaElement::PlayInternal(ErrorResu
   // When the play() method on a media element is invoked, the user agent must
   // run the following steps.
 
   // 4.8.12.8 - Step 1:
   // If the media element is not allowed to play, return a promise rejected
   // with a "NotAllowedError" DOMException and abort these steps.
   if (!IsAllowedToPlay()) {
     // NOTE: for promise-based-play, will return a rejected promise here.
+    LOG(LogLevel::Debug,
+        ("%p Play() promise rejected because not allowed to play.", this));
     aRv.Throw(NS_ERROR_DOM_MEDIA_NOT_ALLOWED_ERR);
     return nullptr;
   }
 
   // 4.8.12.8 - Step 2:
   // If the media element's error attribute is not null and its code
   // attribute has the value MEDIA_ERR_SRC_NOT_SUPPORTED, return a promise
   // rejected with a "NotSupportedError" DOMException and abort these steps.
   if (GetError() && GetError()->Code() == MEDIA_ERR_SRC_NOT_SUPPORTED) {
+    LOG(LogLevel::Debug,
+        ("%p Play() promise rejected because source not supported.", this));
     aRv.Throw(NS_ERROR_DOM_MEDIA_NOT_SUPPORTED_ERR);
     return nullptr;
   }
 
   // 4.8.12.8 - Step 3:
   // Let promise be a new promise and append promise to the list of pending
   // play promises.
   RefPtr<Promise> promise = CreateDOMPromise(aRv);
@@ -4073,16 +4117,19 @@ HTMLMediaElement::PlayInternal(ErrorResu
       nsresult rv = mDecoder->Play();
       if (NS_FAILED(rv)) {
         // We don't need to remove the _promise_ from _mPendingPlayPromises_ here.
         // If something wrong between |mPendingPlayPromises.AppendElement(promise);|
         // and here, the _promise_ should already have been rejected. Otherwise,
         // the _promise_ won't be returned to JS at all, so just leave it in the
         // _mPendingPlayPromises_ and let it be resolved/rejected with the
         // following actions and the promise-resolution won't be observed at all.
+        LOG(LogLevel::Debug,
+            ("%p Play() promise rejected because failed to play MediaDecoder.",
+             this));
         aRv.Throw(rv);
         return nullptr;
       }
     }
   }
 
   if (mCurrentPlayRangeStart == -1.0) {
     mCurrentPlayRangeStart = CurrentTime();
@@ -6808,31 +6855,43 @@ HTMLMediaElement::IsAllowedToPlay()
   if (!AutoplayPolicy::IsMediaElementAllowedToPlay(WrapNotNull(this))) {
 #if defined(MOZ_WIDGET_ANDROID)
     nsContentUtils::DispatchTrustedEvent(OwnerDoc(),
                                          static_cast<nsIContent*>(this),
                                          NS_LITERAL_STRING("MozAutoplayMediaBlocked"),
                                          false,
                                          false);
 #endif
+    LOG(LogLevel::Debug,
+        ("%p %s AutoplayPolicy blocked autoplay.", this, __func__));
     return false;
   }
 
+  LOG(LogLevel::Debug,
+      ("%p %s AutoplayPolicy did not block autoplay.", this, __func__));
+
   // Check our custom playback policy.
   if (mAudioChannelWrapper) {
     // Note: SUSPENDED_PAUSE and SUSPENDED_BLOCK will be merged into one single state.
     if (mAudioChannelWrapper->GetSuspendType() == nsISuspendedTypes::SUSPENDED_PAUSE ||
         mAudioChannelWrapper->GetSuspendType() == nsISuspendedTypes::SUSPENDED_BLOCK) {
+      LOG(LogLevel::Debug,
+          ("%p IsAllowedToPlay() returning false due to AudioChannelAgent.",
+           this));
       return false;
     }
 
+    LOG(LogLevel::Debug, ("%p IsAllowedToPlay() returning true.", this));
     return true;
   }
 
   // If the mAudioChannelWrapper doesn't exist that means the CC happened.
+  LOG(LogLevel::Debug,
+      ("%p IsAllowedToPlay() returning false due to null AudioChannelAgent.",
+       this));
   return false;
 }
 
 static const char* VisibilityString(Visibility aVisibility) {
   switch(aVisibility) {
     case Visibility::UNTRACKED: {
       return "UNTRACKED";
     }