Video reports 'ended' event twice if it finishes in background

RESOLVED FIXED in Firefox 55

Status

()

Core
Audio/Video: Playback
RESOLVED FIXED
10 months ago
10 months ago

People

(Reporter: 684sigma, Assigned: kaku)

Tracking

({regression})

55 Branch
mozilla55
regression
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox52 unaffected, firefox-esr52 unaffected, firefox53 unaffected, firefox54 unaffected, firefox55 fixed)

Details

MozReview Requests

()

Submitter Diff Changes Open Issues Last Updated
Loading...
Error loading review requests:

Attachments

(5 attachments, 1 obsolete attachment)

(Reporter)

Description

10 months ago
I have a problem in Firefox Nightly 55. It doesn't happen in Firefox Beta 52, Beta 53.
Sometimes when I switch to a tab with web page that contains finished video, some glitches occur. I figured out that it happens because 'ended' event is reported twice.
I noticed one specific scenario when it happens

1. Open https://www.youtube.com/watch?v=Sqz5dbs5zmo
2. Seek video to the end. Press "J" twice, pause the video.
3. Execute in console this code, then switch to another tab
var v = document.querySelector('video'); v.volume=0.1; v.onended=function(){console.log(1234);console.log('a');};
4. Wait 25 seconds, switch back to the Youtube tab

1. Open https://www.ssyoutube.com/watch?v=Sqz5dbs5zmo , download the video. Open the downloaded video.
2. Press End. Press Left.
3. Execute in console this code, then switch to another tab
var v = document.querySelector('video'); v.volume=0.1; v.onended=function(){console.log(1234);console.log('a');};
4. Wait 20 seconds, switch back to the tab with video

Result: 'ended' is reported twice
Expected: once
Assignee: nobody → kaku
Component: Audio/Video → Audio/Video: Playback
(Reporter)

Comment 1

10 months ago
Sorry, Comment 0 is contains a mistake: after executing JavaScript code, it's necessary to play the video and only after that switch to another tab. I won't copy paste all text again because of this small change.
I guess I can make a screen record if it's really necessary.

Comment 2

10 months ago
These STR are not very clear, I don't understand why thre are 2 parts 1/2/3/4, just write unique STR chapter. In addition, I don't see any "ended" event in the console.
(Reporter)

Comment 3

10 months ago
str
(In reply to Loic from comment #2)
> These STR are not very clear, I don't understand why thre are 2 parts
> 1/2/3/4, just write unique STR chapter. In addition, I don't see any "ended"
> event in the console.

Alright, I'll write correct steps and change the code to log exactly 'ended' event.

1. Open https://www.ssyoutube.com/watch?v=Sqz5dbs5zmo , download the video. Open the downloaded video.
2. Execute in console this code, then click on the video
var v = document.querySelector('video');v.volume = 0.1;v.pause();v.currentTime=v.duration-15;v.onended = e => console.log(e);onclick = (e) => {e.preventDefault();v.play();W = window.open();setTimeout('W.close()', 20000);};
3. Wait in opened "about:blank" tab 20 seconds, until it closes itself

Result: 'ended' event is logged twice in the original tab with video. Happens with every video longer than 10s.
Expected: 'ended' event should be logged once, because the video finishes only once.
Comment hidden (mozreview-request)
(In reply to JW Wang [:jwwang] [:jw_wang] from comment #4)
> Created attachment 8849912 [details]
> Bug 1349097. P1 - add a test case.
> 
> Review commit: https://reviewboard.mozilla.org/r/122656/diff/#index_header
> See other reviews: https://reviewboard.mozilla.org/r/122656/

Add a mochitest to repro the issue.

Comment 6

10 months ago
Regression range:
https://hg.mozilla.org/integration/autoland/pushloghtml?fromchange=b84a197304d6e5e6bcbcefc8c2bbedbc0053f2bd&tochange=1f9d289e8272f27659bf980528b6d89f61f7ac87

Regressed by your bug 1317576, JW Wang.
Blocks: 1317576
Status: UNCONFIRMED → NEW
Has Regression Range: --- → yes
Has STR: --- → yes
status-firefox52: --- → unaffected
status-firefox53: --- → affected
status-firefox54: --- → affected
status-firefox55: --- → affected
status-firefox-esr52: --- → unaffected
Ever confirmed: true
Keywords: regression
OS: Unspecified → All
Hardware: Unspecified → All
Version: 55 Branch → 53 Branch
(In reply to Loic from comment #6)
> Regression range:
> https://hg.mozilla.org/integration/autoland/
> pushloghtml?fromchange=b84a197304d6e5e6bcbcefc8c2bbedbc0053f2bd&tochange=1f9d
> 289e8272f27659bf980528b6d89f61f7ac87
> 
> Regressed by your bug 1317576, JW Wang.

No. I think it is regressed by the suspend-backround-video-decode feature. Can you try to repro the issue with "media.suspend-bkgnd-video.enabled" set to false in about:config?
Flags: needinfo?(epinal99-bugzilla2)

Comment 8

10 months ago
Indeed, with media.suspend-bkgnd-video.enabled=false, it's not reprodcible.
Flags: needinfo?(epinal99-bugzilla2)
(Assignee)

Comment 9

10 months ago
So, the problem is that a suspend video element becomes visible after the playback finished and we try to resume the element video decoder and trigger a seek operation which seeks to the end of the video and then trigger the 2nd ended event.

We should handle this issue by overriding the HandleResumeVideoDecoding() handler for CompletedState. The overridden behavior should not trigger a seek operation but still pass information to the reader.

A patch is following.
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)

Comment 13

10 months ago
mozreview-review
Comment on attachment 8850892 [details]
Bug 1349097 P4 - add a mochitest;

https://reviewboard.mozilla.org/r/123414/#review125824

::: dom/media/test/test_background_video_ended_event.html:13
(Diff revision 1)
> +<script type="text/javascript">
> +"use strict";
> +
> +var manager = new MediaTestManager;
> +
> +function testDelay(v, start, min) {

Unused function.

::: dom/media/test/test_background_video_ended_event.html:20
(Diff revision 1)
> +  let delay = end - start;
> +  ok(delay > min, `${v.token} suspended with a delay of ${delay} ms`);
> +}
> +
> +startTest({
> +  desc: 'Test Background Video Suspends',

Test background video doesn't fire the 'ended' event twice.

::: dom/media/test/test_background_video_ended_event.html:29
(Diff revision 1)
> +    [ "media.suspend-bkgnd-video.delay-ms", 100 ]
> +  ],
> +  tests: gDecodeSuspendTests,
> +  runTest: (test, token) => {
> +    let v = appendVideoToDoc(test.name, token);
> +    manager.started(token);ㄋ

ㄋ???

::: dom/media/test/test_background_video_ended_event.html:33
(Diff revision 1)
> +    let v = appendVideoToDoc(test.name, token);
> +    manager.started(token);ㄋ
> +
> +    let count = 0;
> +    v.addEventListener("ended", function() {
> +      is(++count, 1, `${token} got ${count} ended events.`);

${token} should get only one 'ended' event.
Attachment #8850892 - Flags: review?(jwwang) → review+

Comment 14

10 months ago
mozreview-review
Comment on attachment 8850891 [details]
Bug 1349097 P1 - don't switch to SEEKING state while resuming video decoder in COMPLETED state;

https://reviewboard.mozilla.org/r/123412/#review125826

We need to resume decoding so the user can see the last frame when switching the tab to foreground.
Attachment #8850891 - Flags: review?(jwwang) → review-
(Assignee)

Updated

10 months ago
Depends on: 1350852
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
(Assignee)

Updated

10 months ago
Attachment #8850891 - Attachment is obsolete: true

Comment 19

10 months ago
mozreview-review
Comment on attachment 8851943 [details]
Bug 1349097 P3 - don't dispatch another ended event while resuming the video decoder of an already-ended playback;

https://reviewboard.mozilla.org/r/124144/#review126734

::: dom/media/MediaDecoderStateMachine.cpp:1896
(Diff revision 1)
>        mMaster->ScheduleStateMachine();
>      }
>    }
>  
>  private:
> -  bool mSentPlaybackEndedEvent = false;
> +  // If a video element was invisible and becomes visible with its playback had

I think it is simpler to early return in MediaDecoder::PlaybackEnded() if the state is already PLAY_STATE_ENDED.
Attachment #8851943 - Flags: review?(jwwang) → review-

Comment 20

10 months ago
mozreview-review
Comment on attachment 8851942 [details]
Bug 1349097 P2 - let CompletedState::HandleResumeVideoDecoding() seek to the last video frame;

https://reviewboard.mozilla.org/r/124142/#review126736

::: dom/media/MediaDecoderStateMachine.cpp:1877
(Diff revision 1)
>    }
>  
> +  void HandleResumeVideoDecoding(Maybe<int64_t> aTarget) override
> +  {
> +    // Resume the video decoder and seek to the last video frame.
> +    // This triggers a video-only seek which won't update the playback position.

http://searchfox.org/mozilla-central/rev/7419b368156a6efa24777b21b0e5706be89a9c2f/dom/media/MediaDecoderStateMachine.cpp#1824

I think it will still update the playback position which is visible to the user because mVideoCompleted is false after video-only seeking and UpdatePlaybackPositionPeriodically() will be run.
Kaku,
This is a 53 regression bug. Allow me to remind you of this bug still on your plate. :-)
Flags: needinfo?(kaku)
After discussing with Kaku offline, this is not a 53 regression bug.
status-firefox53: affected → unaffected
status-firefox54: affected → unaffected
Version: 53 Branch → 55 Branch
(Assignee)

Comment 23

10 months ago
Thanks and will keep working on this bug.
Flags: needinfo?(kaku)
(Assignee)

Comment 24

10 months ago
mozreview-review-reply
Comment on attachment 8851942 [details]
Bug 1349097 P2 - let CompletedState::HandleResumeVideoDecoding() seek to the last video frame;

https://reviewboard.mozilla.org/r/124142/#review126736

> http://searchfox.org/mozilla-central/rev/7419b368156a6efa24777b21b0e5706be89a9c2f/dom/media/MediaDecoderStateMachine.cpp#1824
> 
> I think it will still update the playback position which is visible to the user because mVideoCompleted is false after video-only seeking and UpdatePlaybackPositionPeriodically() will be run.

Yes, UpdatePlaybackPositionPeriodically() will be run but it will return early at 
http://searchfox.org/mozilla-central/rev/72fe012899a1b27d34838ab463ad1ae5b116d76b/dom/media/MediaDecoderStateMachine.cpp#3495-3497

So, I think this patch works, make sense?

Comment 25

10 months ago
mozreview-review-reply
Comment on attachment 8851942 [details]
Bug 1349097 P2 - let CompletedState::HandleResumeVideoDecoding() seek to the last video frame;

https://reviewboard.mozilla.org/r/124142/#review126736

> Yes, UpdatePlaybackPositionPeriodically() will be run but it will return early at 
> http://searchfox.org/mozilla-central/rev/72fe012899a1b27d34838ab463ad1ae5b116d76b/dom/media/MediaDecoderStateMachine.cpp#3495-3497
> 
> So, I think this patch works, make sense?

That would be good.

Comment 26

10 months ago
mozreview-review
Comment on attachment 8851941 [details]
Bug 1349097 P1 - let HandleResumeVideoDecoding() take a const TimeUnit& argument;

https://reviewboard.mozilla.org/r/124140/#review128038

::: dom/media/MediaDecoderStateMachine.cpp:3059
(Diff revision 1)
>  
>    // If suspend timer exists, destroy it.
>    CancelSuspendTimer();
>  
>    if (mVideoDecodeSuspended) {
> -    mStateObj->HandleResumeVideoDecoding();
> +    mStateObj->HandleResumeVideoDecoding(Nothing());

Passing Nothing() is confusing. We should just pass GetMediaTime() here to specify the location to resume video-decoding.
Attachment #8851941 - Flags: review?(jwwang) → review-

Comment 27

10 months ago
mozreview-review
Comment on attachment 8851942 [details]
Bug 1349097 P2 - let CompletedState::HandleResumeVideoDecoding() seek to the last video frame;

https://reviewboard.mozilla.org/r/124142/#review128040

::: dom/media/MediaDecoderStateMachine.cpp:1878
(Diff revision 1)
>  
> +  void HandleResumeVideoDecoding(Maybe<int64_t> aTarget) override
> +  {
> +    // Resume the video decoder and seek to the last video frame.
> +    // This triggers a video-only seek which won't update the playback position.
> +    StateObject::HandleResumeVideoDecoding(Some(mMaster->mDecodedVideoEndTime));

Per bug 1352319, we want to use TimeUnit whenever possible.
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)

Comment 33

10 months ago
mozreview-review
Comment on attachment 8851941 [details]
Bug 1349097 P1 - let HandleResumeVideoDecoding() take a const TimeUnit& argument;

https://reviewboard.mozilla.org/r/124140/#review129788
Attachment #8851941 - Flags: review?(jwwang) → review+

Comment 34

10 months ago
mozreview-review
Comment on attachment 8851942 [details]
Bug 1349097 P2 - let CompletedState::HandleResumeVideoDecoding() seek to the last video frame;

https://reviewboard.mozilla.org/r/124142/#review129790
Attachment #8851942 - Flags: review?(jwwang) → review+

Comment 35

10 months ago
mozreview-review
Comment on attachment 8851943 [details]
Bug 1349097 P3 - don't dispatch another ended event while resuming the video decoder of an already-ended playback;

https://reviewboard.mozilla.org/r/124144/#review129792
Attachment #8851943 - Flags: review?(jwwang) → review+
(Assignee)

Comment 36

10 months ago
Try looks good and thanks for the review!

Comment 37

10 months ago
Pushed by tkuo@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/bb8d67f46396
P1 - let HandleResumeVideoDecoding() take a const TimeUnit& argument; r=jwwang
https://hg.mozilla.org/integration/autoland/rev/ae02de16afef
P2 - let CompletedState::HandleResumeVideoDecoding() seek to the last video frame; r=jwwang
https://hg.mozilla.org/integration/autoland/rev/d5c046fa8845
P3 - don't dispatch another ended event while resuming the video decoder of an already-ended playback; r=jwwang
https://hg.mozilla.org/integration/autoland/rev/4ca8539197bd
P4 - add a mochitest; r=jwwang

Comment 38

10 months ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/bb8d67f46396
https://hg.mozilla.org/mozilla-central/rev/ae02de16afef
https://hg.mozilla.org/mozilla-central/rev/d5c046fa8845
https://hg.mozilla.org/mozilla-central/rev/4ca8539197bd
Status: NEW → RESOLVED
Last Resolved: 10 months ago
status-firefox55: affected → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla55
You need to log in before you can comment on or make changes to this bug.