1398139 - dom/media/mediasource/test/test_WaitingToEndedTransition_mp4.html fails on windows and mac 10.12

Status: RESOLVED FIXED

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

Description

[Joel Maher ( :jmaher ) (UTC -8)]

we are moving our windows 8 tests on hardware to windows 10 hardware- same hardware, different operating system.

for the media tests, only 1 test fails:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=014799f4c401f271d60c20a3f2d5970478978599&filter-searchStr=media

here is a log file:
https://archive.mozilla.org/pub/firefox/try-builds/[e-mail]-014799f4c401f271d60c20a3f2d5970478978599/try-win64-debug/try_win10_64-debug_test-mochitest-media-e10s-bm110-tests1-windows-build1.txt.gz


and here is a related bit from the log file:
05:34:15     INFO - TEST-PASS | dom/media/mediasource/test/test_WaitingToEndedTransition_mp4.html | fetchWithXHR load uri='bipbop/bipbop_video1.m4s' status=200 
05:34:15     INFO - TEST-PASS | dom/media/mediasource/test/test_WaitingToEndedTransition_mp4.html | fetchWithXHR load uri='bipbop/bipbop_video2.m4s' status=200 
05:34:15     INFO - TEST-PASS | dom/media/mediasource/test/test_WaitingToEndedTransition_mp4.html | fetchWithXHR load uri='bipbop/bipbop_video3.m4s' status=200 
05:34:15     INFO - TEST-PASS | dom/media/mediasource/test/test_WaitingToEndedTransition_mp4.html | fetchWithXHR load uri='bipbop/bipbop_video4.m4s' status=200 
05:34:15     INFO - TEST-PASS | dom/media/mediasource/test/test_WaitingToEndedTransition_mp4.html | fetchWithXHR load uri='bipbop/bipbop_video5.m4s' status=200 
05:34:15     INFO - Loading buffer: [0, 23860)
05:34:15     INFO - SourceBuffer buffered ranges grew from TimeRanges:  to TimeRanges: [0, 0.801666)
05:34:15     INFO - Loading buffer: [0, 21595)
05:34:15     INFO - SourceBuffer buffered ranges grew from TimeRanges: [0, 0.801666) to TimeRanges: [0, 1.601666)
05:34:15     INFO - Loading buffer: [0, 23429)
05:34:15     INFO - SourceBuffer buffered ranges grew from TimeRanges: [0, 1.601666) to TimeRanges: [0, 2.403333)
05:34:15     INFO - Loading buffer: [0, 22446)
05:34:15     INFO - SourceBuffer buffered ranges grew from TimeRanges: [0, 2.403333) to TimeRanges: [0, 3.203333)
05:34:15     INFO - Loading buffer: [0, 18191)
05:34:15     INFO - SourceBuffer buffered ranges grew from TimeRanges: [0, 3.203333) to TimeRanges: [0, 3.838344)
05:34:15     INFO - Invoking play()
05:34:15     INFO - TEST-PASS | dom/media/mediasource/test/test_WaitingToEndedTransition_mp4.html | Video playing. It should play for a bit, then fire 'waiting' 
05:34:15     INFO - Buffered messages logged at 05:34:15
05:34:15     INFO - TEST-PASS | dom/media/mediasource/test/test_WaitingToEndedTransition_mp4.html | Video has correct duration: 3.854512 
05:34:15     INFO - Buffered messages finished
05:34:15     INFO - TEST-UNEXPECTED-FAIL | dom/media/mediasource/test/test_WaitingToEndedTransition_mp4.html | Video has correct currentTime. - got 3.85452, expected 3.854512
05:34:15     INFO -     SimpleTest.is@SimpleTest/SimpleTest.js:312:5
05:34:15     INFO -     @dom/media/mediasource/test/test_WaitingToEndedTransition_mp4.html:47:7
05:34:15     INFO -     promise callback*@dom/media/mediasource/test/test_WaitingToEndedTransition_mp4.html:24:5
05:34:15     INFO -     promise callback*@dom/media/mediasource/test/test_WaitingToEndedTransition_mp4.html:16:3
05:34:15     INFO -     bootstrapTest@dom/media/mediasource/test/mediasource.js:29:5
05:34:15     INFO - GECKO(7368) | MEMORY STAT | vsize 1632MB | vsizeMaxContiguous 129993121MB | residentFast 103MB | heapAllocated 23MB
05:34:15     INFO - TEST-OK | dom/media/mediasource/test/test_WaitingToEndedTransition_mp4.html | took 5016ms

Comment 1

[Joel Maher ( :jmaher ) (UTC -8)]

:mreavy, could you help find someone to look at this failure?  I suspect this is something easy to fix, although I didn't see anything in the test file that would indicate there is special code for windows.

Comment 2

[Maire Reavy [:mreavy]]

Blake -- is this something that someone on your team could look at?  I'm cc'ing Anthony too.

Comment 3

[Blake Wu [:bwu][:blakewu]]

(In reply to Maire Reavy [:mreavy] Plz needinfo? from comment #2)
> Blake -- is this something that someone on your team could look at?  I'm
> cc'ing Anthony too.
Yeah. 
From comment 0, it looks related to MSE. 
Alastor, 
Can you check this bug? It should interest you.

Comment 4

[Joel Maher ( :jmaher ) (UTC -8)]

I am going to migrate these tests tomorrow to windows 10 and disable this single test- this is a friendly reminder that as of tomorrow it will be needed to enable this test in the manifest. see bug 1398244 for the patch which will be disabling this.

Comment 5

[Alastor Wu [:alwu]]

I can also reproduce this issue on Win7.

Comment 6

[Joel Maher ( :jmaher ) (UTC -8)]

thanks for working on this :alwu, please remember to enable this for win10 in the manifest!

Comment 7

[Alastor Wu [:alwu]]

Offline discussed with JW, it's reasonable that |me.currentTime| might be not equal with |me.duration|, but it should only have very very little difference. 

That is because every platform has different audio backend, and it would affect the audio playback duration according to different hardware resampling rate, even with the same audio samples count.

However, according to spec [1], the |me.duration| should be the last defined position on the media timeline. |me.currentTime| should not exceed the |me.duration| because it's also on the media timeline.

We should correct the |me.currentTime| and don't let it exceeds the |me.duration|.

[1] https://html.spec.whatwg.org/multipage/media.html#media-timeline

Comment 8

[Alastor Wu [:alwu]]

Attachment: Bug 1398139 - part1 : revert the changing of bug 1386478.

According to spec [1], the |ME.duration| should be the last defined position on
the media timeline. |ME.currentTime| should not exceed the |ME.duration| because
it's also on the media timeline.

[1] https://html.spec.whatwg.org/multipage/media.html#media-timeline

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

Comment 9

[Alastor Wu [:alwu]]

Attachment: Bug 1398139 - part2 : adjust sample's start time for chained ogg.

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

Comment 10

[Alastor Wu [:alwu]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=d6c654cb326d6c728d34fdbbb92868b10480d5cf

Comment 11

[Jean-Yves Avenard [:jya]]

it also permanently fail on my mac box. I'm not sure the issue is what you describe (discrepency on media decoder). It's not due to windows 10 per say.

To me this is a regression, and you're seeing the same thing on windows.

First rough regression range.
https://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=d942ef54fdf726840a698d2ddcaf989d2c00edbc&tochange=681a2489f6a92a09f87336c4ebfcd55030ffcda1

Comment 12

[Jean-Yves Avenard [:jya]]

Comment on attachment 8908045 [details]
Bug 1398139 - part1 : revert the changing of bug 1386478.

https://reviewboard.mozilla.org/r/179742/#review185144

::: dom/media/MediaDecoder.cpp:982
(Diff revision 1)
>    MOZ_ASSERT(NS_IsMainThread());
>    MOZ_DIAGNOSTIC_ASSERT(!IsShutdown());
>  
>    double currentPosition = CurrentPosition().ToSeconds();
> -  if (mPlayState == PLAY_STATE_ENDED) {
> -    currentPosition = std::max(currentPosition, mDuration);
> +  if (mPlayState == PLAY_STATE_ENDED ||
> +      currentPosition > mDuration) {

you're assuming you have a valid duration.

that's not always the case.

in fact plenty of media have no valid duration, and as playback goes, the duration is updated.

So why wouldn't the currentTime be different to the duration once it ends once again.

seems to me it's the duration you need to adjust, not the current position.

in any case, I'm not sure this is what the problem is

Comment 13

[Jean-Yves Avenard [:jya]]

test case to easily find a regression

Comment 14

[Jean-Yves Avenard [:jya]]

It's bug 1386478

Comment 15

[Jean-Yves Avenard [:jya]]

I can reproduce on windows 10 by forcing the output refresh rate.
The bipbop is 22.05kHz, so the data will be resampled.

I can reproduce the issue on all platforms. That's what's going on here... I think the assessment in comment 7 is incorrect: nothing to do with the difference in decoders. it's all to do with the AudioSink

You can test by setting the pref media.resampling.enabled to true.
the default rate is 48kHz.

this will cause the test to fail.

In windows 10 try machines, the AudioStream::GetPreferredRate() returns 48000.

On linux that uses pulseaudio the default is 44.1kHz. the upsampling there is exact.

Comment 16

[Alastor Wu [:alwu]]

(In reply to Jean-Yves Avenard [:jya] from comment #12)
> in fact plenty of media have no valid duration, and as playback goes, the
> duration is updated.

We've considered that. Even the metadata has wrong duration, we still update it to make it correct during playback. Because of that, we can always make sure the current position is on the last position on the media time line.

> So why wouldn't the currentTime be different to the duration once it ends
> once again.
> 
> seems to me it's the duration you need to adjust, not the current position.
> 
> in any case, I'm not sure this is what the problem is

The main reason is we don't want the current position exceed the duration, it's defined in the spec.

In addition, as JW said, if the difference is unavoidable, that we don't need to expose this tiny difference to client side.

(In reply to Jean-Yves Avenard [:jya] from comment #11)
> it also permanently fail on my mac box. I'm not sure the issue is what you
> describe (discrepency on media decoder). It's not due to windows 10 per say.

Weird, no issue on my mac OSX 10.11.4.

Comment 17

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

Even if we revert bug 1386478, will 'MediaSource.duration=x' guarantee the end time of the last audio sample equals 'x'?

Comment 18

[Jean-Yves Avenard [:jya]]

(In reply to Alastor Wu [:alwu][please needinfo me][GMT+8] from comment #16)
> (In reply to Jean-Yves Avenard [:jya] from comment #12)
> > in fact plenty of media have no valid duration, and as playback goes, the
> > duration is updated.
> 
> We've considered that. Even the metadata has wrong duration, we still update
> it to make it correct during playback. Because of that, we can always make
> sure the current position is on the last position on the media time line.
> 
> > So why wouldn't the currentTime be different to the duration once it ends
> > once again.
> > 
> > seems to me it's the duration you need to adjust, not the current position.
> > 
> > in any case, I'm not sure this is what the problem is
> 
> The main reason is we don't want the current position exceed the duration,
> it's defined in the spec.
> 
> In addition, as JW said, if the difference is unavoidable, that we don't
> need to expose this tiny difference to client side.

the difference here is due to the resampling in the AudioSink, not the decoder decoding differently between platform

> 
> (In reply to Jean-Yves Avenard [:jya] from comment #11)
> > it also permanently fail on my mac box. I'm not sure the issue is what you
> > describe (discrepency on media decoder). It's not due to windows 10 per say.
> 
> Weird, no issue on my mac OSX 10.11.4.

did you try the steps I mentioned in comment 16?

what sampling rate is going to be used by the AudioSink depends on the audio device connected.
in this test, if your output supports 44.1kHz you won't have an error, if the default sampling rate is 48kHz, then you will have the error.

Comment 19

[Jean-Yves Avenard [:jya]]

(In reply to JW Wang [:jwwang] [:jw_wang] from comment #17)
> Even if we revert bug 1386478, will 'MediaSource.duration=x' guarantee the
> end time of the last audio sample equals 'x'?

that's the intent of this mochitest!

it ensure that the duration is the expected value, and that currentTime is also at the expected value (both for the waiting event and the ended event)

Comment 20

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

Fair enough. We then should fix the chained ogg issue and revert bug 1386478.

Comment 21

[Alastor Wu [:alwu]]

OK, got it.
I will revert the change of bug 1386478 in this bug.

Comment 22

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

(In reply to Alastor Wu [:alwu][please needinfo me][GMT+8] from comment #21)
> OK, got it.
> I will revert the change of bug 1386478 in this bug.

Not until the chained ogg bug is fixed.

Comment 23

[Alastor Wu [:alwu]]

Attachment: Bug 1398139 - part3 : check current time should be increased correctly in new chained part.

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

Comment 24

[Alastor Wu [:alwu]]

Attachment: Bug 1398139 - part4 : enable test.

Fix the fail by patch1, so we can re-enable it.

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

Comment 25

[Alastor Wu [:alwu]]

Comment on attachment 8908045 [details]
Bug 1398139 - part1 : revert the changing of bug 1386478.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/179742/diff/1-2/

Comment 26

[Alastor Wu [:alwu]]

Comment on attachment 8908046 [details]
Bug 1398139 - part2 : adjust sample's start time for chained ogg.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/179744/diff/1-2/

Comment 27

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

Comment on attachment 8908045 [details]
Bug 1398139 - part1 : revert the changing of bug 1386478.

https://reviewboard.mozilla.org/r/179742/#review185356

Comment 28

[Jean-Yves Avenard [:jya]]

Comment on attachment 8908046 [details]
Bug 1398139 - part2 : adjust sample's start time for chained ogg.

https://reviewboard.mozilla.org/r/179744/#review185358

::: commit-message-e56de:1
(Diff revision 2)
> +Bug 1398139 - part2 : adjust the end time of sample for chained ogg file.

this is technically not the correct description.

you're not adjusting the end time, you're adjusting the sample start time.

What about:

adjust sample's start time for chained ogg.

"For chained ogg file" -> "For chained ogg files"

s/previous/previously

Comment 29

[Jean-Yves Avenard [:jya]]

Comment on attachment 8908539 [details]
Bug 1398139 - part3 : check current time should be increased correctly in new chained part.

https://reviewboard.mozilla.org/r/180188/#review185360

Comment 30

[Jean-Yves Avenard [:jya]]

Comment on attachment 8908540 [details]
Bug 1398139 - part4 : enable test.

https://reviewboard.mozilla.org/r/180190/#review185362

can you open a new bug to remove all those windows XP tests?

we no longer supports windows xp.

Comment 31

[Alastor Wu [:alwu]]

(In reply to Jean-Yves Avenard [:jya] from comment #30)
> Comment on attachment 8908540 [details]
> Bug 1398139 - part4 : enable test.
> 
> https://reviewboard.mozilla.org/r/180190/#review185362
> 
> can you open a new bug to remove all those windows XP tests?
> 
> we no longer supports windows xp.

Sure, will do in bug1400195.

Comment 32

[Alastor Wu [:alwu]]

Comment on attachment 8908046 [details]
Bug 1398139 - part2 : adjust sample's start time for chained ogg.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/179744/diff/2-3/

Comment 33

[Alastor Wu [:alwu]]

Comment on attachment 8908539 [details]
Bug 1398139 - part3 : check current time should be increased correctly in new chained part.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/180188/diff/1-2/

Comment 34

[Alastor Wu [:alwu]]

Comment on attachment 8908540 [details]
Bug 1398139 - part4 : enable test.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/180190/diff/1-2/

Comment 35

[Alastor Wu [:alwu]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=215f15a3d14d42fbbcac22d0b44cfdc44198d9c4

Comment 36

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/1421239eef77
part1 : revert the changing of bug 1386478. r=jwwang
https://hg.mozilla.org/integration/autoland/rev/9fe90be81abb
part2 : adjust sample's start time for chained ogg. r=jya
https://hg.mozilla.org/integration/autoland/rev/39e86cbf34d5
part3 : check current time should be increased correctly in new chained part. r=jya
https://hg.mozilla.org/integration/autoland/rev/69fec8b3a6a0
part4 : enable test. r=jya

Comment 37

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

https://hg.mozilla.org/mozilla-central/rev/9fe90be81abb
https://hg.mozilla.org/mozilla-central/rev/39e86cbf34d5
https://hg.mozilla.org/mozilla-central/rev/69fec8b3a6a0