1308939 - HTML5 event discrepancies when changing video sources

Status: RESOLVED INVALID

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

Description

[adam.schenker]

Attachment: HTML5Test.xpi

User Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_10_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/53.0.2785.143 Safari/537.36

Steps to reproduce:

I have provided a simple extension to output some HTML5 event data to the console.

With that installed, perform the following steps:

1. Play a video with a pre-roll advertisement on YouTube
2. Let the ad play until the video switches to the main content
3. Observe the results in the console


Actual results:

Firefox generates the following console output:

video already playing with src=<ad media URL>
event=pause currentSrc=
event=emptied currentSrc=<content video media URL>
event=loadeddata currentSrc=<content video media URL>
event=playing currentSrc=<content video media URL>


Expected results:

Chrome generates the following output with the same extension:

video already playing with src=<ad media URL>
event=pause currentSrc=<ad media URL>
event=ended currentSrc=<ad media URL>
event=emptied currentSrc=<ad media URL>
event=loadeddata currentSrc=<content video media URL>
event=playing currentSrc=<content video media URL>

Please note the following differences between the behaviors:

1. For the "pause" event generated for the switch, Firefox gives an empty value for currentSrc (Chrome gives the ad's media URL).
2. Firefox doesn't generate an "ended" event.
3. Firefox reports the media URL of the main video in currentSrc for all events after the "pause" event. Chrome gives the media URL of the ad until the "loadeddata" event for the main content.

Because of these factors, Firefox does not provide a good indication that the ad video has ended.

Comment 1

[Jean-Yves Avenard [:jya]]

(In reply to adam.schenker from comment #0)
> 3. Firefox reports the media URL of the main video in currentSrc for all
> events after the "pause" event. Chrome gives the media URL of the ad until
> the "loadeddata" event for the main content.

This sounds like an extremely buggy behaviour from chrome if that's what it does...

the mediaURL returned should be the one set. It should return the new URL even before loadedmetadata is even fired.

Also, remember that events are fired asynchronously. The JS will receive the event well after the action has already occurred.

Will investigate on why the ended event isn't fired however. But for the others, that sounds like a chrome bug to me, certainly not the correct behaviour per spec.

Comment 2

[Jean-Yves Avenard [:jya]]

Can't reproduce what you describe....

[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Queuing event durationchange
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Queuing event timeupdate
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Queuing event pause
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Queuing event timeupdate
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Queuing event ended
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Dispatching event timeupdate
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Dispatching event timeupdate
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Dispatching event timeupdate
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Dispatching event durationchange
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Dispatching event timeupdate
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Dispatching event pause
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Queuing event abort
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Queuing event timeupdate
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Queuing event emptied
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Queuing event ratechange
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Queuing event ratechange
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Queuing event ratechange
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Queuing event emptied
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Queuing event ratechange
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Queuing event ratechange
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Queuing event emptied
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Queuing event ratechange
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Queuing event ratechange
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Queuing event play
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Queuing event waiting
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Queuing event loadstart
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Dispatching event emptied
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Dispatching event ratechange
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Dispatching event ratechange
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Dispatching event play
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Dispatching event waiting
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Dispatching event loadstart
--DOMWINDOW == 44 (0x7fcf1c9aa400) [pid = 14135] [serial = 46] [outer = (nil)] [url = https://www.youtube.com/embed/8DWzijA0lwg?adformat=1_8&mute=1&modestbranding=1&autoplay=1&wmode=opaque&nologo=1&iv_load_policy=3&start=0&enablejsapi=1&rel=0&controls=0&showinfo=0&widget_referrer=https%3A%2F%2Fpubads.g.doubleclick.net%2Fgampad%2Fads%3Fad_rule%3D0%26d_imp%3D1%26gdfp_req%3D1%26impl%3Difr%26iu%3D%252F4061%252Fcom.ythome%26scp%3Ddc_yt%253D1%2526kbsg%253DHPFR161010%2526kga%253D-1%2526kgg%253D-1%2526klg%253Den%2526kmyd%253Dvideo-masthead%2526ssl%253D1%2526ytdevice%253D1%2526ytexp%253D9419452%25252C9438820%25252C&origin=https%3A%2F%2Fwww.youtube.com&widgetid=1]
https://www.youtube.com/video_masthead?video_id=8DWzijA0lwg&autocrop=0&site_cta=1&textLine1=Rendez-vous%20le%2011%20octobre&textLine2=&subscribe_button=0&subscriber_count=0&small_autoplay=0&video_wall=0&list=&autoplay_start_time=0&autoplay_duration=30000&cta_label=D%C3%A9couvrez!]
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Queuing event progress
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Dispatching event progress
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Queuing event durationchange
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Queuing event resize
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Queuing event loadedmetadata
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Queuing event loadeddata
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Queuing event canplay
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Queuing event playing
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Queuing event progress
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Dispatching event durationchange
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Dispatching event resize
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Dispatching event loadedmetadata
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Dispatching event loadeddata
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Dispatching event canplay
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Dispatching event playing
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Dispatching event progress
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Queuing event timeupdate
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Queuing event timeupdate
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Queuing event progress
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Queuing event timeupdate
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Queuing event timeupdate
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Queuing event timeupdate
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Dispatching event timeupdate
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Dispatching event timeupdate
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Dispatching event progress
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Queuing event timeupdate
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Queuing event progress
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Dispatching event timeupdate
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Queuing event timeupdate
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Dispatching event timeupdate
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Dispatching event timeupdate
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Queuing event timeupdate
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Dispatching event timeupdate
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Dispatching event progress
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Queuing event progress
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Dispatching event timeupdate
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Queuing event timeupdate
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Dispatching event timeupdate
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Queuing event timeupdate
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Dispatching event progress
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Queuing event canplaythrough
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Dispatching event timeupdate
[Main Thread]: D/nsMediaElementEvents 7fcf3e811000 Queuing event timeupdate

Everything appears everything per spec to me...

ended is fired when the ad finishes playing.

Comment 3

[adam.schenker]

(In reply to Jean-Yves Avenard [:jya] from comment #2)
> Can't reproduce what you describe....
>
> Everything appears everything per spec to me...
> 
> ended is fired when the ad finishes playing.

The issue occurs when a pre-roll ad is playing and then the video switches to the main content. This happens either when the ad finishes or the user clicks a button to skip the ad.

Not all videos on YouTube have pre-roll ads, and those that do will not always show them. The link above did not play any pre-roll for me, it only displayed the main video content.

You may need to look through several videos before you find one with pre-roll. The following channel's videos produce pre-roll ads for me fairly often:

https://www.youtube.com/channel/UCmeds0MLhjfkjD_5acPnFlQ

Comment 4

[Jean-Yves Avenard [:jya]]

The logs above where of course for a video showing pre-load ad.
Ended is fired once the video reaches the end as per spec https://html.spec.whatwg.org/multipage/embedded-content.html#event-media-ended "Playback has stopped because the end of the media resource was reached."

If you mean that ended isn't played if the user press the skip ad button, then as noted above, the ended event shouldn't be fired in this case.

I can't fault our implementation here, if you believe it's wrong, then please linked to the related specs.
What chrome does isn't a valid explanation, seeing here they are most likely wrong about it.

You can also provide the source code of your extension to check on what you're doing to capture the events.

Comment 5

[adam.schenker]

(In reply to Jean-Yves Avenard [:jya] from comment #4)
> The logs above where of course for a video showing pre-load ad.
> Ended is fired once the video reaches the end as per spec
> https://html.spec.whatwg.org/multipage/embedded-content.html#event-media-
> ended "Playback has stopped because the end of the media resource was
> reached."
> 
> If you mean that ended isn't played if the user press the skip ad button,
> then as noted above, the ended event shouldn't be fired in this case.
> 
> I can't fault our implementation here, if you believe it's wrong, then
> please linked to the related specs.
> What chrome does isn't a valid explanation, seeing here they are most likely
> wrong about it.
> 
> You can also provide the source code of your extension to check on what
> you're doing to capture the events.

Here is the code of the extension's injected script:

var HTML5Events = ["playing","pause","ended","seeked","emptied","abort","loadeddata"];
var duplicates = new Array();
setInterval(function(){ processHTML5Videos(window); }, 500);

function processHTML5Videos(win)
{	
	// get all HTML5 video elements
	var videos = win.document.getElementsByTagName("video");
	for (var i = 0; i < videos.length; i++)
	{		
		// add HTML5 event listeners
		for (var j = 0; j < HTML5Events.length; j++)
			videos[i].addEventListener(HTML5Events[j], html5EventListener, false);
		
		// video already playing when event handlers added
		if (videos[i].currentTime > 0 && videos[i].paused == false)
		{	
			var src = videos[i].getAttribute("src");
			
			// check if we have already logged this in the console
			if (duplicates.indexOf(src) == -1)
			{
				console.log("video already playing with src="+src);
				duplicates.push(src);
			}
		}
	}
}

function html5EventListener(e)
{
	console.log("event="+e.type+" currentSrc="+e.target.currentSrc);	
}

With the above code I don't get an "ended" event for pre-roll (even when it reaches the end of the ad). I also get an empty currentSrc for the "pause" event.

Please let me know if you have any suggestions.

Comment 6

[dostoevskey]

Sorry, but the urls from your logs didn't play ad for me too.

Please try to test one more time with this links:
https://www.youtube.com/watch?v=uuwfgXD8qV8
or
https://www.youtube.com/watch?v=8kV_187iPqU&feature=youtu.be

For first time viewing will play ad before the main content starts.

Thank you in advance and happy testing.

Comment 7

[Jean-Yves Avenard [:jya]]

JW, got any ideas on this?

 Running with the logs on always show that ended event is fired. What could cause the extension to not receive it?

Comment 8

[Jean-Yves Avenard [:jya]]

(In reply to dostoevskey from comment #6)
> Sorry, but the urls from your logs didn't play ad for me too.
> 

Ads aren't shown based on the video you are watching, but what you've watched previously and how long it's been since you saw an ad. 

As such, giving a particular video link with the assumption that they will give you an ad is flawed. 

I can tell you that with the logs provided above, an ad was displayed first. What video was playing was irrelevant.

Comment 9

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

(In reply to Jean-Yves Avenard [:jya] from comment #7)
> JW, got any ideas on this?
> 
>  Running with the logs on always show that ended event is fired. What could
> cause the extension to not receive it?

setInterval(function(){ processHTML5Videos(window); }, 500);

Is it possible that the script happens to register event handlers after the events are fired?

Comment 10

[Jean-Yves Avenard [:jya]]

But then, it wouldn't get the pause event either... but it does

Comment 11

[Jean-Yves Avenard [:jya]]

(In reply to dostoevskey from comment #6)

> Thank you in advance and happy testing.

BTW, checking on currentSrc at the time you receive the event is fundamentally flawed.
Remember that events are fired asynchronously.
It is entirely possible that betweeen the time the event was queued and the time the event is actually fired that the media element has changed (such as src being changed).

The behaviour you are seeing with chrome isn't standard and it's pure luck if your code works there.
You should record and store the currentSrc at the time you're setting up the event listener and retrieve it when the event handler is ran. Only this will guarantee that you're getting the proper src.

Comment 12

[dostoevskey]

(In reply to Jean-Yves Avenard [:jya] from comment #11)
> BTW, checking on currentSrc at the time you receive the event is
> fundamentally flawed.
> Remember that events are fired asynchronously.
> It is entirely possible that betweeen the time the event was queued and the
> time the event is actually fired that the media element has changed (such as
> src being changed).
> 
> The behaviour you are seeing with chrome isn't standard and it's pure luck
> if your code works there.
> You should record and store the currentSrc at the time you're setting up the
> event listener and retrieve it when the event handler is ran. Only this will
> guarantee that you're getting the proper src.

Thank you for your research and brief explanation. I appreciate it.