1304134 - video "playing" event not firing with autoplay and low bandwidth

Status: RESOLVED FIXED

(Core :: Audio/Video: Playback, defect, P3)

Description

[dv-web-players+mozilla]

User Agent: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:49.0) Gecko/20100101 Firefox/49.0
Build ID: 20160903125323

Steps to reproduce:

* Throttle bandwidth to <= 1.2 Mbps
* Open Firefox and open the developer console
* Navigate to https://s3.amazonaws.com/video-ads-dev-players-test-media/firefoxMissingPlayingEvent.html
* Wait. The video will autoplay after some time.



Actual results:

* The message "videoElement: playing" is not logged to the console (it is not 100% reproducible, so some some retrying may be needed)
* The message “videoElement.paused=true” switches to “videoElement.paused=false” when playback starts.


Expected results:

* The message "videoElement: playing" is logged to the console (i.e. the video element emits a "playing" event)

Comment 1

[dv-web-players+mozilla]

Small correction: just noticed that the "playing" event was fired, but some 20 seconds after the video started playing.

Comment 2

[Chris Pearce [:cpearce (Not reading bugmail)]]

I expect this is due to us only moving to readyState > HAVE_CURRENT_DATA if we've got enqueued decoded future data. I expect that switching to having readyState determined solely by buffered ranges, as we've been talking about, should fix this.

Comment 3

[JW Wang [:jwwang] [:jw_wang]]

Can you try to repro the issue on Nightly by running: `MOZ_LOG=MediaDecoder:4,nsMediaElement:4 ./mach run` and upload the logs?

Thanks!

Comment 4

[JW Wang [:jwwang] [:jw_wang]]

Sorry. I mean to launch firefox from the console by typing:
`MOZ_LOG=MediaDecoder:4,nsMediaElement:4 ./firefox`.

Comment 5

[JW Wang [:jwwang] [:jw_wang]]

(In reply to Chris Pearce (:cpearce) from comment #2)
> I expect this is due to us only moving to readyState > HAVE_CURRENT_DATA if
> we've got enqueued decoded future data. I expect that switching to having
> readyState determined solely by buffered ranges, as we've been talking
> about, should fix this.

I expect the 1st 'playing' to be fired at currentTime=0 (wrt comment 1) because of MDSM's prerolling which decodes some data (for readyState to change to HAVE_FUTURE_DATA) before starting playback (consuming data).

Comment 6

[dv-web-players+mozilla]

Attachment: Firefox logs

Comment 7

[dv-web-players+mozilla]

Attached the logs. This was with Firefox Nightly (52.0a1), buildId 20160921030221, on Linux. Couldn't get the logs to work on Windows.

Also, it seems the playing event I was seeing is happening after the video pauses waiting for buffer

Comment 8

[JW Wang [:jwwang] [:jw_wang]]

Here is what happens:
1. readyState changes to HAVE_FUTURE_DATA but 'playing' is not fired for IsPotentiallyPlaying() is false.
   http://searchfox.org/mozilla-central/rev/8910ca900f826a9b714607fd23bfa1b37a191eca/dom/html/HTMLMediaElement.cpp#4882
2. readyState changes to HAVE_ENOUGH_DATA and autoplay kicks off.
   http://searchfox.org/mozilla-central/rev/8910ca900f826a9b714607fd23bfa1b37a191eca/dom/html/HTMLMediaElement.cpp#4880
3. 'playing' is not fired because |oldState == HAVE_FUTURE_DATA && mReadyState == HAVE_ENOUGH_DATA|.

Fix:
We should run the "Notify about playing" step when autoplay is kicked off.
https://html.spec.whatwg.org/multipage/embedded-content.html#ready-states:autoplaying-flag

Comment 9

[JW Wang [:jwwang] [:jw_wang]]

Btw there are conflicts between these 2 spec:
https://dev.w3.org/html5/spec-preview/media-elements.html#ready-states
https://html.spec.whatwg.org/multipage/embedded-content.html#dom-media-have_enough_data

The w3c one says 'canplaythrough' is fired at the end while whatwg would fire 'canplaythrough' before proceeding to activate autoplay.

Comment 10

[JW Wang [:jwwang] [:jw_wang]]

https://treeherder.mozilla.org/logviewer.html#?job_id=27882847&repo=try#L1932
Btw, the web platform test expects 'play' to fire before 'canplaythrough'. I guess we still need to follow the w3c spec.

Comment 11

[JW Wang [:jwwang] [:jw_wang]]

Attachment: Bug 1304134. Part 1 - per spec. (https://dev.w3.org/html5/spec-preview/media-elements.html#ready-states) 'playing' should be fired before activating autoplay.

Also replace the check for IsPotentiallyPlaying() with !mPaused because mReadyState >= HAVE_FUTURE_DATA guarantees playback is not ended.

Review commit: https://reviewboard.mozilla.org/r/81000/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/81000/

Comment 12

[JW Wang [:jwwang] [:jw_wang]]

Attachment: Bug 1304134. Part 2 - per spec. fire 'playing' when autoplay is activated.

Review commit: https://reviewboard.mozilla.org/r/81002/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/81002/

Comment 13

[Chris Pearce [:cpearce (Not reading bugmail)]]

Comment on attachment 8794685 [details]
Bug 1304134. Part 1 - per spec. (https://dev.w3.org/html5/spec-preview/media-elements.html#ready-states) 'playing' should be fired before activating autoplay.

https://reviewboard.mozilla.org/r/81000/#review79868

::: dom/html/HTMLMediaElement.cpp:4890
(Diff revision 1)
> -    mWaitingForKey = false;
> +      mWaitingForKey = false;
> -    DispatchAsyncEvent(NS_LITERAL_STRING("playing"));
> +      DispatchAsyncEvent(NS_LITERAL_STRING("playing"));
> -  }
> +    }
> +  }
> +
> +  CheckAutoplayDataReady();

I think you should be doing the CheckAutoplayDataReady() call inside the last block where we fire "canplaythrough", for clarity. CheckAutoplayDataReady() already checks that the readyState is >= HAVE_ENOUGH_DATA, so it shouldn't be a behaviour change.

Comment 14

[Chris Pearce [:cpearce (Not reading bugmail)]]

Comment on attachment 8794686 [details]
Bug 1304134. Part 2 - per spec. fire 'playing' when autoplay is activated.

https://reviewboard.mozilla.org/r/81002/#review79870

While this follows the spec, this does mean that if we transition from readyState < HAVE_FUTURE_DATA to HAVE_ENOUGH_DATA, and the autoplaying flag is true, we'll fire on "playing" event at line 4886, and another in CheckAutoplayDataReady(). i.e. we'll fire two at once.

Comment 15

[JW Wang [:jwwang] [:jw_wang]]

Comment on attachment 8794685 [details]
Bug 1304134. Part 1 - per spec. (https://dev.w3.org/html5/spec-preview/media-elements.html#ready-states) 'playing' should be fired before activating autoplay.

https://reviewboard.mozilla.org/r/81000/#review80508

::: dom/html/HTMLMediaElement.cpp:4890
(Diff revision 1)
> -    mWaitingForKey = false;
> +      mWaitingForKey = false;
> -    DispatchAsyncEvent(NS_LITERAL_STRING("playing"));
> +      DispatchAsyncEvent(NS_LITERAL_STRING("playing"));
> -  }
> +    }
> +  }
> +
> +  CheckAutoplayDataReady();

http://searchfox.org/mozilla-central/rev/5bdd2876aeb9dc97dc619ab3e067e86083dad023/dom/html/HTMLMediaElement.cpp#4972

It is tricky that we want to activate autoplay regardless of the ready state when playing MSE or MediaStream.

Ｉthink this is something we need to fix. The ready state should change to HAVE_ENOUGH_DATA correctly when playing MSE or MediaStream so we can remove the special checks for mSrcStream or mMediaSource

Comment 16

[JW Wang [:jwwang] [:jw_wang]]

Comment on attachment 8794685 [details]
Bug 1304134. Part 1 - per spec. (https://dev.w3.org/html5/spec-preview/media-elements.html#ready-states) 'playing' should be fired before activating autoplay.

https://reviewboard.mozilla.org/r/81000/#review80508

> http://searchfox.org/mozilla-central/rev/5bdd2876aeb9dc97dc619ab3e067e86083dad023/dom/html/HTMLMediaElement.cpp#4972
> 
> It is tricky that we want to activate autoplay regardless of the ready state when playing MSE or MediaStream.
> 
> Ｉthink this is something we need to fix. The ready state should change to HAVE_ENOUGH_DATA correctly when playing MSE or MediaStream so we can remove the special checks for mSrcStream or mMediaSource

I mean we can fix it in next bugs.

Comment 17

[JW Wang [:jwwang] [:jw_wang]]

Comment on attachment 8794686 [details]
Bug 1304134. Part 2 - per spec. fire 'playing' when autoplay is activated.

https://reviewboard.mozilla.org/r/81002/#review79870

No, we won't because the preconditions for firing 'playing' (!mPaused) and autoplay (mPaused) are mutual exclusive.

Comment 18

[JW Wang [:jwwang] [:jw_wang]]

Thanks for the review!

Comment 19

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/bf73c623fb64
Part 1 - per spec. (https://dev.w3.org/html5/spec-preview/media-elements.html#ready-states) 'playing' should be fired before activating autoplay. r=cpearce
https://hg.mozilla.org/integration/autoland/rev/be5121024c7c
Part 2 - per spec. fire 'playing' when autoplay is activated. r=cpearce

Comment 20

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/bf73c623fb64
https://hg.mozilla.org/mozilla-central/rev/be5121024c7c

Comment 21

[Sylvestre Ledru [:Sylvestre]]

Do we want to uplift that to 50 or 51? If so, please submit the uplift request. Thanks

Comment 22

[JW Wang [:jwwang] [:jw_wang]]

Comment on attachment 8794685 [details]
Bug 1304134. Part 1 - per spec. (https://dev.w3.org/html5/spec-preview/media-elements.html#ready-states) 'playing' should be fired before activating autoplay.

Approval Request Comment
[Feature/regressing bug #]:none
[User impact if declined]:Some sites listen to 'playing' event to start playback. Without this fix, 'playing' might not be fired under low bandwidth condition and playback can't start correctly.
[Describe test coverage new/current, TreeHerder]:TreeHerder
[Risks and why]: Low. The change is simple
[String/UUID change made/needed]:none

Comment 23

[Gerry Chang [:gchang]]

Comment on attachment 8794685 [details]
Bug 1304134. Part 1 - per spec. (https://dev.w3.org/html5/spec-preview/media-elements.html#ready-states) 'playing' should be fired before activating autoplay.

Fix a video playback issue under low bandwidth. Take it in 51 aurora.

Comment 24

[Carsten Book [:Tomcat]]

should both parts be uplifted or just part 1 ?

Comment 25

[JW Wang [:jwwang] [:jw_wang]]

Oops! Both parts should be uplifted. Thanks for the reminder.

Comment 26

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/71786422299e
https://hg.mozilla.org/releases/mozilla-aurora/rev/c443c728d92c