Closed Bug 1572705 Opened 6 years ago Closed 6 years ago

Video plays for a few seconds then gives error Media Cannot Be Played

Categories

(Web Compatibility :: Site Reports, defect)

Product:
Web Compatibility
Component:
Site Reports
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(Not tracked)

Status:
RESOLVED WORKSFORME

People

(Reporter: jesup, Unassigned)

References

(
URL
)

Details

Attachments

(1 file)

video.log.child-4.gz
37.76 KB, application/x-gzip
Details

The twitter video on this page will play for a few seconds, then say "The media cannot be played", sometimes flickering back to video once or twice before sitting on that message. Hitting replay typically gives the same sequence.

Reloading may give a different sequence of flickers. Fullscreen doesn't seem to change it.

jesup: what platform are you on? I'm interested in the decoder you're using specifically. For me on linux I end up with ffmpeg, which is playing them without any errors. There appears to be some video corruption (freezes/artifacts) though I'm not sure they're part of the video or. Could you perhaps get us some MediaDecoder:5,MediaDemuxer:5,MP4Metadata:5 logs?

Fwiw twitter fetches this as a HLS .m3u8 playlist of 9 .ts chunks and then plays the chunks through MSE. Not sure what processing they do to be able to play those chunks, but playing them with ffplay I see identical video corruption to what I see in Firefox, and warnings like [AVBSFContext @ 0x7f337c009900] Invalid NAL unit 0, skipping.=0/0 at the beginning of each chunk. Not sure what that has to say here.

Flags: needinfo?(rjesup)

Linux Fedora 29

I saw this on stderr:
[Child 24249, MediaDecoderStateMachine #1] WARNING: Decoder=7f49a8730c00 Decode error: NS_ERROR_DOM_MEDIA_FATAL_ERR (0x806e0005) - RefPtr<MediaSourceTrackDemuxer::SamplesPromise> mozilla::MediaSourceTrackDemuxer::DoGetSamples(int32_t): manager is detached.: file /home/jesup/src/mozilla/inbound/dom/media/MediaDecoderStateMachine.cpp, line 3305

Attaching logs.

Flags: needinfo?(rjesup)

Having a hard time judging the priority of this, but it seems like a generic error so erring on the safe side with P2 for now.

Alastor, the "manager is detached" seems to come from code you've touched. Could you take a look? I didn't see additional clues in the log unfortunately.

jesup, do you also get this under rr? If so, would you be able to upload it to pernosco? You can reach out to me if you need help getting set up.

Flags: needinfo?(rjesup)
Flags: needinfo?(alwu)
Priority: -- → P2

It does repro under rr. First run it only showed the message once and played through to the end; hitting replay showed the same behavior (play, glitch, message, play, message, stops - more or less)

Flags: needinfo?(rjesup)

I can reproduce that, let me check it later and keep NI.

Interesting, that fatal error was not the reason of showing the message "The media cannot be played". It was caused by a racing between MDSM begining to shutdown to MSDM really starting shutdown, because the MFR doesn't know we have released the buffer and then hit the error, which is trying to get a sample after manager detached. It's definitly a problem we shoud fix.

However, this error actually won't be knew by HTMLMediaElement, because we have disconnected the error event listener when we started shutdown MSDM, so that error basicly is like a ghost and both HTMLMediaElement and MediaDecoder won't be aware of that.

So I was really curious why Twitter would think that they can't play media even if we didn't dispatch any error to them (I also checked if we dispatch other error via SourceBuffer, but we didn't). I tried to trace their front-end code to see how they decide to show that error message, but I didn't find any useful information.

Interestingly I can now reproduce. I wonder if this is a recent regression. I'll try first mozregression and then pernosco if that doesn't give anything concrete.

mozregression showed the same behavior all the way back to 57. Pernosco link is at https://pernos.co/debug/8cDiO3XPnZsEtq7sKCs63A/index.html

The STR for the recording:

  • Load the twitter URL
  • Let it play through once with autoplay (didn't show the error)
  • Hit play again (did show the error in Twitter's UI)

Alastor, you want to give it a go?

Yes, I'll continue to debug this issue.

Assignee: nobody → alwu
Flags: needinfo?(alwu)

I'm suspecting this issue is caused by the incorrect video handling logic in Twitter's hls js code.

The first weird thing is that, they would call sourceBuffer.endOfStream() while video is playing near to 6 secs, and then removing the src from media element and calling video.load(), which would remove the media source object attached to media element and detach the source buffer. It's a really uncommon usage for MSE, because we usually use one media source object all the time and appending data on to its source buffer, we don't have to change media source object during playback.

In their hls.js, I found the following code, which would be executed when detaching media source.

t.removeEventListener("sourceopen", this.onmso), t.removeEventListener("sourceended", this.onmse), t.removeEventListener("sourceclose", this.onmsc), this.media && (URL.revokeObjectURL(this.media.src), this.media.removeAttribute("src"), this.media.load()), this.mediaSource = null, this.media = null, this.pendingTracks = {}, this.tracks = {}, this.sourceBuffer = {}, this.flushRange = [], this.segments = [], this.appended = 0

If you watch the video on Twitter page [1], it would use one media source during playback. This issue only happened on visiting Twitter video url directly [2]. So I wonder whether this issue would happen on other video? but I couldn't find any other video (of cource, visiting their url directly) with same symptom.

[1] https://twitter.com/elonmusk/status/1158899839456800769?ref_src=twsrc%5Etfw%7Ctwcamp%5Etweetembed%7Ctwterm%5E1158899839456800769&ref_url=https%3A%2F%2Farstechnica.com%2Fscience%2F2019%2F08%2Fspacex-to-launch-a-rare-expendable-mission-on-tuesday-evening%2F

[2] https://twitter.com/i/videos/tweet/1158899839456800769

Therefore, after they detached media source and removed src object, calling video.load() was actually useless, because we have nothing to load from. And I found Twitter would call load() a couple of times, and then I guess that they would show the error mesaage "The media cannot be played" due to loading nothing after calling multiple times of load().

So, there are two questions,
(1) Is calling endOfStream() while video is playing to near 6 sec a mistake? because we won't see that function call when we watch video from the Twitter page, but would see that if we visit video url directly.
(2) After calling endOfStream(), why they decide to reload the media element without having any source attached to media element? It apparently has no effect, is this behavior a reason of resulting in showing the error message "The media cannot be played"?

(In reply to Randell Jesup [:jesup] (needinfo me) from comment #2)

Linux Fedora 29

I saw this on stderr:
[Child 24249, MediaDecoderStateMachine #1] WARNING: Decoder=7f49a8730c00 Decode error: NS_ERROR_DOM_MEDIA_FATAL_ERR (0x806e0005) - RefPtr<MediaSourceTrackDemuxer::SamplesPromise> mozilla::MediaSourceTrackDemuxer::DoGetSamples(int32_t): manager is detached.: file /home/jesup/src/mozilla/inbound/dom/media/MediaDecoderStateMachine.cpp, line 3305

Attaching logs.

This error isn't related to a decoding error that could be exposed to JS. This error is informative only and occurs if a decoding task got queued from the MDSM/MFR but the SourceBuffer/MediaSource object got GCed before that task got to run. This will occur if the used closed the window or the video element got removed from the DOM.

So it's red herring in this context.

(In reply to Alastor Wu [:alwu] from comment #12)

So, there are two questions,
(1) Is calling endOfStream() while video is playing to near 6 sec a mistake? because we won't see that function call when we watch video from the Twitter page, but would see that if we visit video url directly.
(2) After calling endOfStream(), why they decide to reload the media element without having any source attached to media element? It apparently has no effect, is this behavior a reason of resulting in showing the error message "The media cannot be played"?

EndOfStream can be called at any time, it has no impact on playback per say. EndOfStream is just a hint to advised the decoding pipeline that no more data will be added to the source buffers, it will move the MSE readyState to ended and update the media element duration so that it becomes max(audio duration, video duration).

(In reply to Jean-Yves Avenard [:jya] from comment #14)

EndOfStream can be called at any time, it has no impact on playback per say. EndOfStream is just a hint to advised the decoding pipeline that no more data will be added to the source buffers, it will move the MSE readyState to ended and update the media element duration so that it becomes max(audio duration, video duration).

Yes, I know that, but the problem here I would like to raise here is that why they have to have such a difference (calling EndOfStream and reload) between watching video on Twitter page and watching video directly via its url. Especially when clearing the source and reloading media element without any source, which I think might be the reason of resulting showing error message.

I've sent a mail to mozilla-twitter-discuss, to see if Twitter can help to investigate this issue.

So I took a look in Pernosco based on Alastor's findings (good job!). The first MediaSource::EndOfStream that occurs seems to stem from a SourceBuffer "updateend" event (see the Pernosco notebook). It gives ~15 js stack frames, but seems truncated.
Then there's a couple HTMLMediaElement::DoLoad()s. The first one has the same js stack. The second one is higher in the stack, and reveals more, so I've puzzled them together.

(pernosco) call DumpJSStack() 
0 555/</</ir</e.prototype.onMediaDetaching(undefined) ["https://abs.twimg.com/web-video-player/hls.bcccba86b9a047ba.js":1:139278]
    this = [object Object]
1 () ["self-hosted":1061:16]
2 555/</</It</t.prototype.onEventGeneric(t = "hlsMediaDetaching", e = undefined) ["https://abs.twimg.com/web-video-player/hls.bcccba86b9a047ba.js":1:78439]
    this = [object Object]
3 555/</</It</t.prototype.onEvent(t = "hlsMediaDetaching") ["https://abs.twimg.com/web-video-player/hls.bcccba86b9a047ba.js":1:78138]
    this = [object Object]
4 ("hlsMediaDetaching") ["self-hosted":1019:16]
    this = [object Object]
5 555/</</r.prototype.emit(t = "hlsMediaDetaching", "hlsMediaDetaching") ["https://abs.twimg.com/web-video-player/hls.bcccba86b9a047ba.js":1:14200]
    this = [object Object]
6 t/n.trigger(t = "hlsMediaDetaching") ["https://abs.twimg.com/web-video-player/hls.bcccba86b9a047ba.js":1:207676]
    this = [object Object]
7 ("hlsMediaDetaching") ["self-hosted":1019:16]
    this = [object Object]
8 555/</</ki</t.prototype.detachMedia() ["https://abs.twimg.com/web-video-player/hls.bcccba86b9a047ba.js":1:209705]
    this = [object Object]
9 value() ["https://abs.twimg.com/web-video-player/TwitterVideoPlayerIframe.f52b5b572446290e.js":1:225552]
    this = [object Object]
10 value(e = "media_entity", t = "hlsError", n = [object Object]) ["https://abs.twimg.com/web-video-player/TwitterVideoPlayerIframe.f52b5b572446290e.js":1:231246]
    this = [object Object]
11 value("media_entity", "hlsError", [object Object]) ["self-hosted":1023:16]
    this = [object Object]
12 value("hlsError", [object Object]) ["self-hosted":1065:16]
    this = [object Object]
13 555/</</r.prototype.emit(t = "hlsError", "hlsError", [object Object]) ["https://abs.twimg.com/web-video-player/hls.bcccba86b9a047ba.js":1:14200]
    this = [object Object]
14 t/n.trigger(t = "hlsError", [object Object]) ["https://abs.twimg.com/web-video-player/hls.bcccba86b9a047ba.js":1:207676]
    this = [object Object]
15 ("hlsError", [object Object]) ["self-hosted":1021:16]
    this = [object Object]
7 555/</</Oe</e.prototype._loadFragmentOrKey(t = [object Object], e = 0, r = [object Object], i = 6.0075, a = 6.014811) ["https://abs.twimg.com/web-video-player/hls.bcccba86b9a047ba.js":1:105728]
    this = [object Object]
8 555/</</Oe</e.prototype._fetchPayloadOrEos(t = 6.0075, e = [object Object], r = [object Object]) ["https://abs.twimg.com/web-video-player/hls.bcccba86b9a047ba.js":1:103063]
    this = [object Object]
9 555/</</Oe</e.prototype._doTickIdle() ["https://abs.twimg.com/web-video-player/hls.bcccba86b9a047ba.js":1:102494]
    this = [object Object]
10 555/</</Oe</e.prototype.doTick() ["https://abs.twimg.com/web-video-player/hls.bcccba86b9a047ba.js":1:100972]
    this = [object Object]
11 555/</</Oe</e.prototype.tick() ["https://abs.twimg.com/web-video-player/hls.bcccba86b9a047ba.js":1:100772]
    this = [object Object]
12 555/</</Oe</e.prototype._checkAppendedParsed() ["https://abs.twimg.com/web-video-player/hls.bcccba86b9a047ba.js":1:118828]
    this = [object Object]
13 555/</</Oe</e.prototype.onBufferAppended(t = [object Object]) ["https://abs.twimg.com/web-video-player/hls.bcccba86b9a047ba.j

Then after a couple HTMLMediaElement::DoLoad with more or less the original stack, the media element is removed from the DOM. A new DoLoad() has the stack:

0 value() ["https://abs.twimg.com/web-video-player/TwitterVideoPlayerIframe.f52b5b572446290e.js":1:226584]
    this = [object Object]
1 e/this.reload() ["https://abs.twimg.com/web-video-player/TwitterVideoPlayerIframe.f52b5b572446290e.js":1:183822]
    this = [object Object]
2 e/this.onStoreUpdate/<() ["https://abs.twimg.com/web-video-player/TwitterVideoPlayerIframe.f52b5b572446290e.js":1:185001]
    this = [object Window]

Then finally HTMLMediaElement::SetSrc() (and playback can continue):

0 555/</</ir</e.prototype.onMediaAttaching(t = [object Object]) ["https://abs.twimg.com/web-video-player/hls.bcccba86b9a047ba.js":1:139122]
    this = [object Object]
1 () ["self-hosted":1061:16]
2 555/</</It</t.prototype.onEventGeneric(t = "hlsMediaAttaching", e = [object Object]) ["https://abs.twimg.com/web-video-player/hls.bcccba86b9a047ba.js":1:78439]
    this = [object Object]
3 555/</</It</t.prototype.onEvent(t = "hlsMediaAttaching", e = [object Object]) ["https://abs.twimg.com/web-video-player/hls.bcccba86b9a047ba.js":1:78138]
    this = [object Object]
4 ("hlsMediaAttaching", [object Object]) ["self-hosted":1021:16]
    this = [object Object]
5 555/</</r.prototype.emit(t = "hlsMediaAttaching", "hlsMediaAttaching", [object Object]) ["https://abs.twimg.com/web-video-player/hls.bcccba86b9a047ba.js":1:14200]
    this = [object Object]
6 t/n.trigger(t = "hlsMediaAttaching", [object Object]) ["https://abs.twimg.com/web-video-player/hls.bcccba86b9a047ba.js":1:207676]
    this = [object Object]
7 ("hlsMediaAttaching", [object Object]) ["self-hosted":1021:16]
    this = [object Object]
8 555/</</ki</t.prototype.attachMedia(t = [object HTMLVideoElement]) ["https://abs.twimg.com/web-video-player/hls.bcccba86b9a047ba.js":1:209600]
    this = [object Object]
9 value/<(a = [function]) ["https://abs.twimg.com/web-video-player/TwitterVideoPlayerIframe.f52b5b572446290e.js":1:238306]

Looks to me like they're interpreting an "updateend" event as an error (without an "error" event!). Would be interesting to know why. There are plenty of "updateend" they're not treating as errors so something is special here.

We have updated an underlying library (guessed above) which had particular issues with PTS holes. Are you still able to reproduce? Is there a specific browser version I should be testing with? - @gkindel

Yes, I can still reproduce this issue on all Firefox version (69/70/71).

Flags: needinfo?(gkindel)

Sorry to hear that you can repo. I'm still not able to reproduce on 68/70 using the iframe link.

We should be able to play most anything HLS.js can play (demo link)
https://hls-js.netlify.com/demo/?src=https%3A%2F%2Fvideo.twimg.com%2Fext_tw_video%2F1158899801712238592%2Fpu%2Fpl%2FyDYXkPjXqIYihU74.m3u8%3Ftag%3D10&demoConfig=eyJlbmFibGVTdHJlYW1pbmciOnRydWUsImF1dG9SZWNvdmVyRXJyb3IiOnRydWUsImVuYWJsZVdvcmtlciI6dHJ1ZSwiZHVtcGZNUDQiOmZhbHNlLCJsZXZlbENhcHBpbmciOi0xLCJsaW1pdE1ldHJpY3MiOi0xLCJ3aWRldmluZUxpY2Vuc2VVcmwiOiIifQ==

I definitely buffer hole, but we're successfully skipping over it in my tests.

The reloading the media element is an after detect of an error being detected in stream management.

Flags: needinfo?(gkindel)

I can reproduce consistently on Twitter but never on the hls.js demo. This is on Nightly 71 on Ubuntu 18.04.

(In reply to Greg Kindel [:twitter] from comment #20)

Sorry to hear that you can repo. I'm still not able to reproduce on 68/70 using the iframe link.

We should be able to play most anything HLS.js can play (demo link)
https://hls-js.netlify.com/demo/?src=https%3A%2F%2Fvideo.twimg.com%2Fext_tw_video%2F1158899801712238592%2Fpu%2Fpl%2FyDYXkPjXqIYihU74.m3u8%3Ftag%3D10&demoConfig=eyJlbmFibGVTdHJlYW1pbmciOnRydWUsImF1dG9SZWNvdmVyRXJyb3IiOnRydWUsImVuYWJsZVdvcmtlciI6dHJ1ZSwiZHVtcGZNUDQiOmZhbHNlLCJsZXZlbENhcHBpbmciOi0xLCJsaW1pdE1ldHJpY3MiOi0xLCJ3aWRldmluZUxpY2Vuc2VVcmwiOiIifQ==

I definitely buffer hole, but we're successfully skipping over it in my tests.

The reloading the media element is an after detect of an error being detected in stream management.

Maybe there's a bug there then, since hls.js doesn't expose any errors for this video but Twitter does.

To summarize, this seems like a Twitter issue. Moving to webcompat.

Assignee: alwu → nobody
Component: Audio/Video: Playback → Desktop
Priority: P2 → --
Product: Core → Web Compatibility

That's great. It should work for you on https://twitter.com/elonmusk/status/1158899839456800769, the iframe player is updated a bit after

That does work, thanks! Can you ping this bug when the iframe player has been updated so we can re-check?

Heads up that the iframe player has been updated.

I can confirm this works for me now too. Thanks for the update Greg.

Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: