1164080 - HTML5 audio playback on Firefox 37 on Mac terminates song prematurely

Status: RESOLVED WORKSFORME

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

Description

[Dave Edwards]

User Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.9; rv:37.0) Gecko/20100101 Firefox/37.0
Build ID: 20150415140819

Steps to reproduce:

This problem occurs on the Mac using Firefox 37 HTML5 audio playback (I've tried 37.0.1 and 37.0.2, and it's in both), but not in Firefox 36.  It can be reproduced using Pandora, and Listener Support at Pandora has confirmed that dozens of users have contacted them about this behavior.  Pandora is working around this by defaulting to use Flash for audio playback.  Experiments can be run using Pandora by forcing either HTML5 audio playback or Flash playback using the following URLs:

To force HTML5 playback: http://www.pandora.com/?disableForceFlash=true
To force Flash playback: http://www.pandora.com/?forceFlash=true

To reproduce, log into Pandora (you can sign up for free if you don't already have an account) and pick a station, and start playing songs.  This won't occur on every song, but for me I've never had it go more than 10 songs without occurring.


Actual results:

A song will suddenly terminate in the middle (at a random point) and go to the next song.  Presumably this is due to the way Pandora handles an error code from the audio player, but the point is that the same Pandora code reacts differently with the HTML5 player on Firefox 36 vs. 37, and it reacts differently with HTML5 audio playback vs. Flash audio playback on Firefox 37.


Expected results:

When using Flash, you will hear an audio "glitch" or "stutter" every 5 or 6 songs on average, and it doesn't appear to be connected to network load.  It could be related to streaming clock drift (http://en.wikipedia.org/wiki/Drift_%28telecommunication%29) or to interference from other Pandora traffic (ads).  With HTML5 playback on Firefox 36, I didn't find the audio glitching to be as noticeable as with Flash.  But both Firefox 37 with Flash and Firefox 36 with HTML5 correctly absorb minor sound impact to the playback and continue playing the song.

Some notes:  If this is stimulated by clock drift, your particular experience of the frequency of occurrence will vary depending on your hardware.  If it's related to Pandora ad traffic, your experience could vary depending on what ads are delivered to you.  But again, dozens of listeners who don't know each other have all reported this behavior, and Pandora has confirmed all instances are tied to Firefox 37 on the Mac.

Comment 1

[(not reading bugmail) Nick Desaulniers [:\n]]

I've seen this happen.

In the response headers, I see a Content Length: bytes 0-4263948/4263949
for a request with the header Range: "bytes=0-"

In the console I also see: HTTP "Content-Type" of "text/html" is not supported. Load of media resource about:blank failed.

That looks like you tried to assign the source attribute of the audio element to a URL that responded with a content type of "text/html" and not "audio/mp4" like was expected.

I'm guessing that the server is incorrectly handling byte range requests (off by 1), then when the browser makes the subsequent request, the server responds with an incorrect MIME type, the browser barfs, triggering onerror.

If you addEventListeners to #jp_audio_0 for ended and error events, you'll see ended fire followed by error.

I would expect we would see an additional network request in out dev tools for the subsequent request for the last byte, which would have the MIME type set incorrectly, but maybe on error our dev tools don't log it, which would be a bug.

@Paul, did anything related to byte range requests change from 37+?  Am I on the right track?

I would assume Pandora's CDN is misconfigured in regards of the byte range requests.  And it looks like it's based on User Agent header.  If I load it up in Opera, the response header for the mp4 is:

Content-Length:3054240

so Pandora's CDN is sending messed up byte range responses only to FF.

Comment 2

[Paul Adenot (:padenot)]

Sorry Nick, I'm completely out of the loop of media playback changes these days, 302 to :k17e.

Comment 3

[(not reading bugmail) Nick Desaulniers [:\n]]

Hm, trying to switch my User Agent in FF via an add on, I get the same behavior.  Further, I tested another app I know works with byte range requests and see that there is no off by 1 error.  The Content-Range response header is in the range format 0-<length minus 1>/<length>.  Unless the media team knows of any recent changes in audio tags or events, Pandora should probably speak with their vendor, jPlayer.

Comment 4

[:Harald Kirschner :digitarald]

ni? on Pandora QA as Nick is expecting their input

-ni? for ajones until it's confirmed to be on the platform side.

Comment 5

[Anthony Jones (:ajones, :kentuckyfriedtakahe, :k17e)]

Can you provide an example URL that fails? Is it reproducible when replaying the same track?

Comment 6

[Dave Edwards]

No, the bug doesn't seem tied to particular tracks.  It's not reliably reproducible at a particular point, but seems roughly correlated with total elapsed time of audio playback.  For example, on my computer it happens roughly every 5 or 6 songs (although this is approximate and it doesn't ALWAYS hold).  I don't have enough sample data to draw any further correlations, such as with song length.  It also doesn't seem to have a pattern as to where in the song it will suddenly terminate, it could be near the beginning, in the middle, or near the end.

We can investigate the "off by one" observation, but I'm left wondering why the problem doesn't occur in Firefox 36 with the exact same Pandora instance.

Comment 7

[(not reading bugmail) Nick Desaulniers [:\n]]

I've experienced it; but sporadically.  I usually listen to music for a few minutes and maybe 1 in every 3 songs will terminate early.  The "off by one" is not a problem; a misnomer on my part.

Comment 8

[Anthony Jones (:ajones, :kentuckyfriedtakahe, :k17e)]

I haven't been able to reproduce the issue. If it is a clock drift related issue then it could be related to bug 1136360. Getting any errors reported to the Javascript from the Pandora side would be nice.

Nick - can you try to get a log using:

MEDIA_LOG_SAMPLES=1 NSPR_LOG_MODULES=MediaDecoder:5,MediaSource:5,MediaPromise:5,nsMediaElement:5,nsMediaElementEvents:5

Comment 9

[(not reading bugmail) Nick Desaulniers [:\n]]

sure, excuse my ignorance, but I'm not familiar with what I do with those params?  Are the mozconfig params for a debug build, or prefs, or what?

Comment 10

[Anthony Jones (:ajones, :kentuckyfriedtakahe, :k17e)]

Nick - I asked you because I thought you might've dealt with NSPR logging before. Fortunately for me Mac OSX isn't significantly different to Linux in this instance. This means that either you or Dave (the reporter) can do the following:

$ export MEDIA_LOG_SAMPLES=1
$ export NSPR_LOG_MODULES=MediaDecoder:5,MediaSource:5,MediaPromise:5,nsMediaElement:5,nsMediaElementEvents:5
$ /Applications/Firefox.app/Contents/MacOS/firefox | tee pandora.log

Comment 11

[Dave Edwards]

Collected debug info as requested.  Talk about luck, the problem occurred within the first minute of playback, and is about 10 seconds from the end of the log.  The file pandora.log is attached.

Comment 12

[Dave Edwards]

Attachment: Log file with debug info during an occurrence of the error

Debug log of problem occurrence.

Comment 13

[Anthony Jones (:ajones, :kentuckyfriedtakahe, :k17e)]

Matt - can you use your superior log inspection skills to take a look at this issue?

Comment 14

[Matt Woodrow (:mattwoodrow)]

It certainly looks like we're playing audio right up to the end. I wonder if it's possible that we're playing silence somehow?

Comment 15

[Dave Edwards]

Audio was playing the whole time, it just terminated one song prematurely and immediately started the next one.  Hopefully what will show up in the log is why it failed/terminated the first song.

Comment 16

[Matt Woodrow (:mattwoodrow)]

Ok, sorry, I misinterpreted the problem initially.

The file is reporting as 215 seconds long, but after 61 seconds we get this:

38619392[124204710]: Error rejecting MediaPromise (1239b0510 created at RequestAudioData)\
738619392[124204710]: <chained promise> rejecting MediaPromise (1238feec0 created at EnsureAudioDecodeTaskQueued)\
738619392[124204710]: Rejecting Then() call made from EnsureAudioDecodeTaskQueued [Runnable=11cd5d440, Promise=1238feec0, ThenValue=1239b04c0]\
738619392[124204710]: MediaPromise::~MediaPromise [this=1238feec0]\
738619392[124204710]: MediaPromise::~MediaPromise [this=1239b0510]\
738619392[124204710]: RejectRunnable::Run() [this=11cd5d440]\
738619392[124204710]: Decoder=122d0a370 OnNotDecoded (aType=0, aReason=1)\
738619392[124204710]: Decoder=122d0a370 Change machine state from DECODING to SHUTDOWN\
667947008[10e243ff0]: Decoder=122d0a370 StopPlayback()\
667947008[10e243ff0]: Decoder=122d0a370 Shutdown audio thread\
756289536[1242052f0]: AudioSink=11dd06710 AudioLoop complete\

OnNotDecoded with aReason=1 is DECODE_ERROR, which is coming from MP4Reader::Error.

Can you please get another log with AppleMedia:5 included in the logging option so we hopefully get more information on why decoding failed.

Anthony, jya, any more thoughts here? Should a decode error terminate playback, or should we attempt to skip over it?

Comment 17

[Jean-Yves Avenard [:jya]]

I opened a bug for that a while back: bug 1069720.

However, according to the spec:
https://html.spec.whatwg.org/multipage/embedded-content.html#media-data-processing-steps-list

"If the media data is corrupted"

which leads to "Abort the overall resource selection algorithm."

making any error effectively fatal.

Comment 18

[Jean-Yves Avenard [:jya]]

There seems to be a new section since I last looked:

"If the media data can be fetched but has non-fatal errors or uses, in part, codecs that are unsupported, preventing the user agent from rendering the content completely correctly but not preventing playback altogether

    The server returning data that is partially usable but cannot be optimally rendered must cause the user agent to render just the bits it can handle, and ignore the rest.
"

I guess we could make it fall under this category. skipping decoding of an audio frame is trivial as all audio frames can be considered as keyframe. Video on the other hand is more complicated as not being able to decode a frame may make others frames impossible to decode should they relied on that frame.

Comment 19

[Matt Woodrow (:mattwoodrow)]

I'm interpreting that to mean "if an error can be ignored, then it should be". So that's something we could look into once we figure out what the actual error is in this case.

Comment 20

[Anthony Jones (:ajones, :kentuckyfriedtakahe, :k17e)]

(In reply to Jean-Yves Avenard [:jya] from comment #18)
> I guess we could make it fall under this category. skipping decoding of an
> audio frame is trivial as all audio frames can be considered as keyframe.
> Video on the other hand is more complicated as not being able to decode a
> frame may make others frames impossible to decode should they relied on that
> frame.

The logic would be to skip to the next keyframe in either case.

Comment 21

[Jean-Yves Avenard [:jya]]

I've been playing music for the past 30 minutes, I'm yet to get a decode error...
Do you have a particular stream I could test with?

Comment 22

[Dave Edwards]

(In reply to Jean-Yves Avenard [:jya] from comment #21)
> I've been playing music for the past 30 minutes, I'm yet to get a decode
> error...
> Do you have a particular stream I could test with?

The problems aren't tied to particular streams.  Occurrence seems to vary on different machines, and my best theory is that it's triggered by clock drift (see the last paragraph of the description).  If correct, that would mean the frequency of occurrence would be related to the relationship of the clock speed on your machine compared to the server.

Comment 23

[Anthony Jones (:ajones, :kentuckyfriedtakahe, :k17e)]

(In reply to ucla79grad from comment #22)
> The problems aren't tied to particular streams.  Occurrence seems to vary on
> different machines, and my best theory is that it's triggered by clock drift
> (see the last paragraph of the description).  If correct, that would mean
> the frequency of occurrence would be related to the relationship of the
> clock speed on your machine compared to the server.

That isn't what comment 16 says. It should be possible to test your theory by creating a deliberate clock-skew.

Comment 24

[Ryan VanderMeulen [:RyanVM]]

Bug 865827 looks related to this one too.

Comment 25

[Ryan VanderMeulen [:RyanVM]]

(In reply to Ryan VanderMeulen [:RyanVM UTC-4] from bug 865827 comment #36)
> I listed to Pandora on a Win10 trunk build for many hours today (using
> http://www.pandora.com/?disableForceFlash=true and denying the Flash
> click-to-play prompt to ensure HTML audio). I heard many ads during that
> time. Playback never stopped.
> 
> Can anybody still reproduce the issue this bug was filed for?

Comment 26

[Dave Edwards]

(In reply to Ryan VanderMeulen [:RyanVM UTC-4] from comment #25)
> (In reply to Ryan VanderMeulen [:RyanVM UTC-4] from bug 865827 comment #36)
> > I listed to Pandora on a Win10 trunk build for many hours today (using
> > http://www.pandora.com/?disableForceFlash=true and denying the Flash
> > click-to-play prompt to ensure HTML audio). I heard many ads during that
> > time. Playback never stopped.
> > 
> > Can anybody still reproduce the issue this bug was filed for?

I'm on Firefox for Mac version 41.0.2, using the exact same machine, network, and configuration as when I reported the problem.  I haven't listened for long enough to positively conclude this isn't occurring any more, however, it's gone longer without occurring than it ever has since I reported it.  I'll continue listening and if I don't hear any occurrences after several hours of listening, I'll close this issue.

Comment 27

[Dave Edwards]

I spent about 3 hours total listening under the same circumstances as when the problem was originally reported.  It used to occur within 30-40 minutes without fail, but now didn't occur at all for the 3 hours.  It seems with the latest version (41.0.2) this problem no longer occurs, so I'm marking it as resolved.

Comment 28

[Ryan VanderMeulen [:RyanVM]]

Thanks for getting back so soon!