1065855 - MediaSource seekable range is empty when it should not be if endOfStream is not called in some instances

Status: RESOLVED FIXED

(Core :: Audio/Video, defect)

Description

[cajbir (:cajbir)]

The seekable attribute contains an empty range in some instances when it should not. The case I've struck is of there is more than one appendBuffer done but no endOfStream() called. At loadedmetadata time there is no seekable range and the resource cannot be seeked.

I see, and have tests for which I'll attach:

1. one appendBuffer of entire file, endOfStream(). Seekable is valid, media source can be seeked.
2. one appendBuffer of entire file, no endOfStream(). Seekable is valid, media source can be seeked.
3. two appendBuffer, first portion of file followed by rest, endOfStream(). Seekable is valid, media source can be seeked.
4. two appendBuffer, first portion of file followed by rest, no endOfStream(). Seekable is empty, media source cannot be seeked.

Comment 1

[cajbir (:cajbir)]

Attachment: Tests

Tests the four cases mentioned in comment 0.

Comment 2

[cajbir (:cajbir)]

Test test_SeekableBeforeEndOfStreamSplit.html is failing because the SetMediaSourceDuration call in MediaSourceReader::ReadMetadata is failing the test that no SourceBuffer can be in the updating state.

Comment 3

[cajbir (:cajbir)]

I suspect we shouldn't be going through those checks when setting the duration as defined in the spec since we are setting it internally during the updated event.

Comment 4

[cajbir (:cajbir)]

Attachment: Ignore updating check when setting MediaSource Duration within a SourceBuffer append

Sets the media source duration directly by using the DurationChange method when setting it ourselves. This avoids the check that we have a source buffer in the udpating state - which we do because we are setting it during the update.

Comment 5

[cajbir (:cajbir)]

Attachment: Tests

Tests fail before attachment 8487700 [details] [diff] [review] is applied and pass after.

Comment 6

[cajbir (:cajbir)]

Try: https://tbpl.mozilla.org/?tree=Try&rev=a7f5285a1d2a

Comment 7

[Matthew Gregan [:kinetik]]

Comment on attachment 8487700 [details] [diff] [review]
Ignore updating check when setting MediaSource Duration within a SourceBuffer append

Review of attachment 8487700 [details] [diff] [review]:
-----------------------------------------------------------------

::: content/media/mediasource/MediaSource.h
@@ +100,5 @@
>  
>  private:
> +  // MediaSourceDecoder uses DurationChange to set the duration
> +  // without hitting the checks in SetDuration.
> +  friend class mozilla::MediaSourceDecoder;

Does this need the mozilla::?

Comment 8

[cajbir (:cajbir)]

(In reply to Matthew Gregan [:kinetik] from comment #7)
> 
> Does this need the mozilla::?

Yeah, it doesn't compile without. I was surprised but a search for details on friend suggested the namespace was needed.

Comment 9

[Matthew Gregan [:kinetik]]

Comment on attachment 8487701 [details] [diff] [review]
Tests

Review of attachment 8487701 [details] [diff] [review]:
-----------------------------------------------------------------

Comments for test_SeekableAfterEndOfStream.html apply to all four tests.

::: content/media/mediasource/test/mochitest.ini
@@ +13,5 @@
>  [test_SplitAppend.html]
> +[test_SeekableAfterEndOfStream.html]
> +[test_SeekableAfterEndOfStreamSplit.html]
> +[test_SeekableBeforeEndOfStream.html]
> +[test_SeekableBeforeEndOfStreamSplit.html]

Alpha-sort please.

::: content/media/mediasource/test/test_SeekableAfterEndOfStream.html
@@ +27,5 @@
> +    fetchWithXHR("seek.webm", function (arrayBuffer) {
> +      sb.appendBuffer(new Uint8Array(arrayBuffer));
> +      sb.addEventListener("updateend", function () {
> +        updateCount++;
> +        is(updateCount, 1, "updateend event received");

Move the updateend received check to test_MediaSource, I'd like to have one test (or set of tests, if we need to split it out) that cover the basic sanity type stuff, and keep tests like this one very specific to a particular issue to make test maintenance easier over time.

@@ +37,5 @@
> +
> +    var loadedmetadataCount = 0;
> +    v.addEventListener("loadedmetadata", function () {
> +      loadedmetadataCount++;
> +      is(loadedmetadataCount, 1, "One loadedmetadata event received"); 

Trailing space.  Move this check too.

Comment 10

[cajbir (:cajbir)]

Attachment: Tests

Address review comments and address failures from try run.

Comment 11

[cajbir (:cajbir)]

Try: https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=3e16de5e6295

Comment 12

[cajbir (:cajbir)]

https://hg.mozilla.org/integration/mozilla-inbound/rev/8a945498a0e4
https://hg.mozilla.org/integration/mozilla-inbound/rev/2605dfc0996d

Comment 13

[Phil Ringnalda (:philor)]

Backed out in https://hg.mozilla.org/integration/mozilla-inbound/rev/b252971fb544 - failing your own test on your push like https://tbpl.mozilla.org/php/getParsedLog.php?id=47941226&tree=Mozilla-Inbound is just too much too soon.

Comment 14

[cajbir (:cajbir)]

I suspect this could be the playback stopping in a Wait() call for data or something that we see occasionally. I've managed to reproduce it once in a 1,000 repeat run. Investigating.

Comment 15

[cajbir (:cajbir)]

Running the test 1,000 times looping occasionally hits these warnings and the test times out:

[19884] WARNING: Decoder=7f973e2fb200 ReadMetadata failed, res=0 HasValidMedia=0: file content/media/MediaDecoderStateMachine.cpp, line 1938
[19884] WARNING: Decoder=7f973e2fb200 Decode metadata failed, shutting down decoder: file content/media/MediaDecoderStateMachine.cpp, line 1902
[19884] WARNING: Decoder=7f973e2fb200 Decode error, changed state to SHUTDOWN due to error: file content/media/MediaDecoderStateMachine.cpp, line 1875

The ReadMetadata call looks to be failing because of the check in MediaSourceReader::ReadMetadata:

 if (waiting) {
    return NS_OK;
  }

I'll add some logging to confirm.

Comment 16

[cajbir (:cajbir)]

MediaDecoderStateMachine checks for IsWaitingMediaResources and bails before ReadMetadata if it is waiting. Between the time of that check, and the ReadMetadata call the result of IswaitingMediaResources changes to true, causing the ReadMetadata return.

Comment 17

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

(In reply to cajbir (:cajbir) from comment #16)
> MediaDecoderStateMachine checks for IsWaitingMediaResources and bails before
> ReadMetadata if it is waiting. Between the time of that check, and the
> ReadMetadata call the result of IswaitingMediaResources changes to true,
> causing the ReadMetadata return.

I think bug 1050667 comment 33 is addressing this issue.

Comment 18

[cajbir (:cajbir)]

(In reply to JW Wang [:jwwang] from comment #17)
> 
> I think bug 1050667 comment 33 is addressing this issue.

Will this address the issue for non Omx readers?

Comment 19

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

I think not. MSE is not taken into account when the patch is rolling out.

Comment 20

[cajbir (:cajbir)]

I'm thinking that checking the IsWaitingMediaResources before calling ReadMetadata, while it's under the lock, should prevent the issue unless I'm missing something. Will test.

Comment 21

[cajbir (:cajbir)]

Local testing of 10k+ test runs shows no timeout with the fix described in comment 20. Try run: https://tbpl.mozilla.org/?tree=Try&rev=8cf231822d04

Comment 22

[cajbir (:cajbir)]

Attachment: Fix for hanging test

As described in comment 16, MediaDecoderStateMachine checks for IsWaitingMediaResources and bails before ReadMetadata if it is waiting. Between the time of that check, and the ReadMetadata call the result of IsWaitingMediaResources changes to true, causing the ReadMetadata return.

Fix is to check IsWaitingMediaResources before doing ReadMetadata while we have the lock. This ensures we don't do the ReadMetadata while we are waiting for a media resource. Tests pass in 10,000 local runs which used to fail before and try run in comment 21 looks ok.

Comment 23

[Matthew Gregan [:kinetik]]

Comment on attachment 8489699 [details] [diff] [review]
Fix for hanging test

(In reply to cajbir (:cajbir) from comment #22)
> Created attachment 8489699 [details] [diff] [review]
> Fix for hanging test
> 
> As described in comment 16, MediaDecoderStateMachine checks for
> IsWaitingMediaResources and bails before ReadMetadata if it is waiting.
> Between the time of that check, and the ReadMetadata call the result of
> IsWaitingMediaResources changes to true, causing the ReadMetadata return.

I'm not quite sure I follow, IsWaitingForResources is only checked after calling ReadMetadata as far as I can see.  Based on that, I'd guess what's happening is that IsWaitingForResources returns true inside MediaSourceReader::ReadMetadata and causes an early NS_OK, but by the time the state machine reacquires the lock and checks IsWaitingForResources it is false, so we fall through to the non-waiting path.  Does that make sense or am I missing something?

> Fix is to check IsWaitingMediaResources before doing ReadMetadata while we
> have the lock. This ensures we don't do the ReadMetadata while we are
> waiting for a media resource. Tests pass in 10,000 local runs which used to
> fail before and try run in comment 21 looks ok.

This is similar to what the call to IsWaitingMediaResources inside MediaSourceReader::ReadMetadata is attempting to do, but that approach appears to be racy, so this change makes sense but we should remove the call from MSR::ReadMetadata as it should not be necessary.  I'll f+, but I think cpearce should review this.

(BTW, the test syntax changed slightly in 8dcf6f569697, so you'll need to rebase before landing, but the changes will be trivial to make.)

Comment 24

[cajbir (:cajbir)]

(In reply to Matthew Gregan [:kinetik] from comment #23)
> I'm not quite sure I follow, IsWaitingForResources is only checked after
> calling ReadMetadata as far as I can see.  Based on that, I'd guess what's
> happening is that IsWaitingForResources returns true inside
> MediaSourceReader::ReadMetadata and causes an early NS_OK, but by the time
> the state machine reacquires the lock and checks IsWaitingForResources it is
> false, so we fall through to the non-waiting path.  Does that make sense or
> am I missing something?

Correct.

> This is similar to what the call to IsWaitingMediaResources inside
> MediaSourceReader::ReadMetadata is attempting to do, but that approach
> appears to be racy, so this change makes sense but we should remove the call
> from MSR::ReadMetadata as it should not be necessary. 

Sure, if you agree that it can be removed that looks fine. I wasn't sure if there was another reason for it being there.

> (BTW, the test syntax changed slightly in 8dcf6f569697, so you'll need to
> rebase before landing, but the changes will be trivial to make.)

Ok.

Comment 25

[cajbir (:cajbir)]

Attachment: Ignore updating check when setting MediaSource Duration within a SourceBuffer append

Rebased. Carry forward r+.

Comment 26

[cajbir (:cajbir)]

Attachment: Check for waiting media resources before calling ReadMetadata

Rebased and removed check from ReadMetadata as suggested in comment 23.

Comment 27

[cajbir (:cajbir)]

Attachment: Tests

Tests rebased on 8dcf6f569697 as per comment 23.

Comment 28

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

Comment on attachment 8489766 [details] [diff] [review]
Check for waiting media resources before calling ReadMetadata

Review of attachment 8489766 [details] [diff] [review]:
-----------------------------------------------------------------

Ideally we'd have some sort of promise/event which runs when we're done waiting for resources, but this will do for now.

Comment 29

[cajbir (:cajbir)]

Attachment: Tests

Missed that removeChild no longer needed on parent.

Comment 30

[cajbir (:cajbir)]

https://hg.mozilla.org/integration/mozilla-inbound/rev/b742dd3aece6
https://hg.mozilla.org/integration/mozilla-inbound/rev/97e08c477d63
https://hg.mozilla.org/integration/mozilla-inbound/rev/d462269d88a9

Comment 31

[Carsten Book [:Tomcat]]

sorry had to back this out for test failures like https://tbpl.mozilla.org/php/getParsedLog.php?id=48178648&tree=Mozilla-Inbound and needed to back this out because of conflicts with the tests while backing out

Comment 32

[Carsten Book [:Tomcat]]

(In reply to Carsten Book [:Tomcat] from comment #31)
> sorry had to back this out for test failures like
> https://tbpl.mozilla.org/php/getParsedLog.php?id=48178648&tree=Mozilla-
> Inbound and needed to back this out because of conflicts with the tests
> while backing out

note backedout was https://hg.mozilla.org/integration/mozilla-inbound/rev/d462269d88a9

Comment 33

[cajbir (:cajbir)]

The failure in comment 31 causing the backout looks to be bug 1064705 comment 5, not related to this bug. I'll reland.

Comment 34

[cajbir (:cajbir)]

On investigation, the backup in comment 32 was the commit with the tests only. And these tests weren't the ones that were failing. If the fixes in the bug were causing the failure then they're still in. Was the wrong thing backed out?

Comment 35

[cajbir (:cajbir)]

Oh, missed the end of comment 31. The tests here were backed out because of conflicts backing out the actual problematic one. I'll rebase and reland that commit.

Comment 36

[cajbir (:cajbir)]

Try run for rebased patch: https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=64e6ca87bf5a

Comment 37

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/b742dd3aece6
https://hg.mozilla.org/mozilla-central/rev/97e08c477d63

Comment 38

[cajbir (:cajbir)]

Relanded tests: https://hg.mozilla.org/integration/mozilla-inbound/rev/490b8cb576f9

Comment 39

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/490b8cb576f9