Bug 1439473 - Improve logging of HTMLMediaElement JS API calls. r=kamidphish
authorChris Pearce <cpearce@mozilla.com>
Thu, 15 Feb 2018 16:39:44 +1300
changeset 404817 d2a43ef3a3a6a3c3d6faa4fb354cec5bea9d0187
parent 404781 c1c444858b3282080681201db1dc7082e64e7108
child 404818 43f6075d028ea136010a394fe35ab2306916d982
push id33493
push useraciure@mozilla.com
push dateThu, 22 Feb 2018 21:54:08 +0000
treeherdermozilla-central@2301d04f9cf0 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewerskamidphish
bugs1439473
milestone60.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
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 returns true
  * and puts the range index in aIntervalIndex. If aValue is not
  * inside a range, returns false, and aIntervalIndex
  * is set to the index of the range which starts immediately after aValue
@@ -2893,16 +2925,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;
@@ -2920,16 +2953,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;
 
@@ -3002,16 +3037,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);
@@ -3947,28 +3983,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();
 
@@ -3984,25 +4024,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);
@@ -4044,16 +4088,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();
@@ -6778,31 +6825,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";
     }