1364476 - Pandora stream not playing correctly

Status: VERIFIED FIXED

Description

[Marcia Knous [:marcia - needinfo? me]]

Using Mozilla/5.0 (Macintosh; Intel Mac OS X 10.12; rv:55.0) Gecko/20100101 Firefox/55.0 ID:20170511063838 CSet: 838652a84b76c273e084d0705f3f4f3be89520a8

STR:

1. Open https://www.pandora.com/station/play/3000031766228716931
2. Listen to the stream. Eventually the stream gets messed up and it sounds as if I have 2 audio sources playing.

Comment 1

[Jean-Yves Avenard [:jya]]

This is using Flash, not much we can do about it...

Comment 2

[myfakespamemailacct]

Pandora uses HTML5 now at least there's an <audio> element on the page.

Comment 3

[Jean-Yves Avenard [:jya]]

the page won't load without flash... so hard to say

Comment 4

[myfakespamemailacct]

I went into add ons and disabled the Adobe Shockwave Flash plugin and Pandora doesn't display anything saying it requires Flash.  Is there any additional steps?  I was going to just fire up a virtual machine and install Nightly on it as a way to confirm.  I don't really want to do that unless it's necessary.

Comment 5

[Mike Taylor [:miketaylr] (62 Regression Engineering Owner)]

I can reproduce this in current Nightlies. At some point you end up with more than one <audio> element playing the same track, and they can build up if you hit skip.

Unfortunately mozregression gave a pretty big range between 54 and 55, but I believe this is a regression.

49:19.44 INFO: Switching bisection method to taskcluster
49:19.44 INFO: Getting mozilla-central builds between 0b255199db9d6a6f189b89b7906f99155bde3726 and 37a5b7f6f101df2eb292b1b6baaf1540c9920e20
49:23.02 WARNING: Skipping build 37a5b7f6f101: unable to find a build url for the changeset u'37a5b7f6f101df2eb292b1b6baaf1540c9920e20'
49:24.62 WARNING: Skipping build 17d8a1e278a9: unable to find a build url for the changeset u'17d8a1e278a9c54a6fdda9d390abce4077e55b20'
49:24.82 WARNING: Skipping build c3e5497cff1c: unable to find a build url for the changeset u'c3e5497cff1c995821b1c9320fa71f1ef9a8c30e'
49:25.04 WARNING: Skipping build 22aaf8bad4df: unable to find a build url for the changeset u'22aaf8bad4df8e5f8c976f1521c213cb37e2dff5'
49:26.42 WARNING: Skipping build 81977c96c6ff: unable to find a build url for the changeset u'81977c96c6ff49e4b70f88a55f38d47f5e54a08b'
49:26.44 WARNING: Skipping build 1fda52a1f3b8: unable to find a build url for the changeset u'1fda52a1f3b81cf1a821155998dca637bb64e3d9'
49:26.98 WARNING: Skipping build 38f862749aed: unable to find a build url for the changeset u'38f862749aed4e9a874182a9019e0671289088b0'
49:28.29 WARNING: Skipping build b21b974d60d3: unable to find a build url for the changeset u'b21b974d60d3075ae24f6fb1bae75d0f122f28fc'
49:28.30 WARNING: Skipping build e0955584782e: unable to find a build url for the changeset u'e0955584782e6eb13bb1e7b197d3064660bb756f'
49:28.66 WARNING: Skipping build bab7046ee2d8: unable to find a build url for the changeset u'bab7046ee2d82345d7d5b33b8ae4009c7e365176'
49:30.06 WARNING: Skipping build ec15663c6331: unable to find a build url for the changeset u'ec15663c6331c8227d458bce85e6ca1b37423336'
49:30.26 WARNING: Skipping build b0ff0c5c0a35: unable to find a build url for the changeset u'b0ff0c5c0a35a1ee9f19cec2bae5cc2cd5772db6'
49:30.43 WARNING: Skipping build d715ee055ae7: unable to find a build url for the changeset u'd715ee055ae7d09acf790e40b6742c5241c7501e'
49:32.29 INFO: Expanding higher limit of the range to b9bd73036a92
49:33.65 WARNING: Skipping build e7bf9443be2c: unable to find a build url for the changeset u'e7bf9443be2c4a5187c37440e35f3526148d7fa8'
49:35.08 WARNING: Skipping build 23fe0b76a018: unable to find a build url for the changeset u'23fe0b76a018a5077a0f7234cff91c41e4b6af64'
49:36.54 WARNING: Skipping build ff83fde8be94: unable to find a build url for the changeset u'ff83fde8be946eabcf27ea97d4676f601c122194'
49:37.92 WARNING: Skipping build 9348b76977e8: unable to find a build url for the changeset u'9348b76977e833f108cf77dff75b0fab887a2fc1'
49:40.10 WARNING: Skipping build c273884ffe6b: unable to find a build url for the changeset u'c273884ffe6bb255399bb15fbad6eb0b66be49eb'
49:41.46 WARNING: Skipping build 8872ad4d52b6: unable to find a build url for the changeset u'8872ad4d52b6b517dc9d2a9f62c5c75ceda18790'
49:41.48 INFO: No more inbound revisions, bisection finished.
49:41.48 INFO: Last good revision: 0b255199db9d6a6f189b89b7906f99155bde3726
49:41.48 INFO: First bad revision: b9bd73036a925e44f44ee87e779fbbdb2dbe618c
49:41.48 INFO: Pushlog:
https://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=0b255199db9d6a6f189b89b7906f99155bde3726&tochange=b9bd73036a925e44f44ee87e779fbbdb2dbe618c

Comment 6

[Jean-Yves Avenard [:jya]]

it is my understanding the Pandora only very recently moved to HTML5 from Flash. 

it would be good to know from Pandora under which circumstance do they create a new audio element (and why they don't keep reusing the same one)

Comment 7

[Marcia Knous [:marcia - needinfo? me]]

ni on :dees to see if we have a contact at Pandora that might be able to answer Comment 6.

Comment 8

[Mike Taylor [:miketaylr] (62 Regression Engineering Owner)]

(In reply to Jean-Yves Avenard [:jya] from comment #6)
> it would be good to know from Pandora under which circumstance do they
> create a new audio element (and why they don't keep reusing the same one)

This doesn't answer the "why", but it shows that it's at least intentional:

<audio preload="auto" id="mediaelement_1" src="https://t3-1.p-cdn.com/access/?version=5&amp;lid=1883785137&amp;token=H%2FW27gOIQ5F%2B6mjWzeeHKGj8SliaSl9dLYuByVHF2ugCwIKUGJKbeQ6Xw5trGkyaSSmtdWjZYdlI7BaEyk3bamv5JoeVtDP4yDId3kPAlyWysaEtfcPXoKPtYrBe6rJYAXT2EtRLy3rFaxQAjC7xg6XdOnek%2Benh5Vzz95dJGOPC3Epzu1viv4BlG6tYTc8f42GSSx7GLyFM1ePN8v%2BgU3iDh1IltmekNoi3TInvZQ%2Bcu0mw4bUDWtKzBI99S6ZYwDcxBdi0d5IgQ5Hpr3JDK8RHUk5dBP5H05hMZhR1DPxZvln2bpRptD5yktiexlhLof2BUdxx9%2BcUaf0tKAZT2A%3D%3D" data-reuse-elements="disabled"></audio>

Each new audio element has a data-reuse-elements="disabled" attribute.

https://gist.github.com/miketaylr/52696a79a1c95d200c20bee2863e4df2#file-gistfile2-txt-L1 has the method that's creating and inserting the elements into the DOM, but I haven't gotten the when/why yet.

Comment 9

[Mike Taylor [:miketaylr] (62 Regression Engineering Owner)]

(giving up for now, new debugger in nightly has bugs :( https://github.com/devtools-html/debugger.html/issues/2782#issuecomment-303234237)

Comment 10

[Mike Taylor [:miketaylr] (62 Regression Engineering Owner)]

One other thing, the moment we get the duplicate audio element, we xhr a POST to https://www.pandora.com/api/v1/station/playbackResumed. So why the phantom resuming a non-paused media element...

Comment 12

[alex_mayorga]

¡Hola!

This is not OS X specific.

I see it... err hear it on Firefox 55.0a1 20170530030204 on Win10 as well.

Another thing that happens is that once there are two streams playing, no amount of pausing or muting the tab makes the second stream go away.

¡Gracias!
Alex

Comment 13

[Desigan Chinniah [:cyberdees] [:dees] [London - GMT]]

(In reply to Marcia Knous [:marcia - use ni] from comment #7)
> ni on :dees to see if we have a contact at Pandora that might be able to
> answer Comment 6.

We have a mailing list (same syntax as others) with the Pandora folks. I'm not sure if either :jya :adamopenweb or :miketaylr have already reached out using this channel?

Comment 14

[Mike Taylor [:miketaylr] (62 Regression Engineering Owner)]

We're not ready for outreach yet, IMO. Last week I was in Norway where I couldn't keep working on diagnosis, hopefully will have enough time this week.

Comment 15

[Mike Taylor [:miketaylr] (62 Regression Engineering Owner)]

Any luck here Tom?

Comment 16

[Thomas Wisniewski]

Not yet, but I'll keep at it (I've been caught up in all sorts of diagnosis-work, but tomorrow I'll devote all my time to this one).

Comment 17

[Thomas Wisniewski]

I think I've found the culprit, though it's difficult to parse what's actually causing it. It seems to be being caused by Pandora's client-side scripts making requests with HTTP Range headers that go past the end of the song.

Here's some background. Sometimes during a song's playback an error of some sort happens, and the "We are experiencing trouble playing audio" message appears. It seems to recover sometimes, only logging a message to the console:

  ERROR  Client/actions/Stats:  Stats API call failed

This seems to be triggered by a MutationCallback that's in turn triggered by a setTimeout. A call is made to drainQueues, a promise is ultimately rejected somewhere, handled by a settlePromiseFromHandler method, and that's that.

However, sometimes things don't recover as nicely. The same message appears, similar code appears to happen, but instead of doing the above a GET request is made to a server's "access" endpoint (ie https://audio-sv5-t1-2-v4v6.pandora.com/access/). However, the response to that request is a 400/Bad Request. This is then followed by an XMLHttpRequest POST to "playbackResumed" (ie https://www.pandora.com/api/v1/station/playbackResumed). Then a "new Audio" context is created, and we end up with the current song playing twice (one in the old context, one in the new, slightly out of sync). When each context finishes playing the song, they both begin playing a completely new song. And the problem can repeat for each, from what I can tell.

Here's the Curl-equivalent of one request which triggers the 400 response:

curl 'https://audio-dc6-t1-1-v4v6.pandora.com/access/?version=5&lid=1634790290&token=N2kpXRRCIgR4GqcxGRmEZHajPi73PHmVbmO1bQdVRp3Ivj1A6QjRJPFT%2BFcudGGz3MzFbprc1l7yGBQDs2ftY%2BYqfpRV2W%2FqcirPXdHQRm2StbNPHdHXAF46y9kgr9NgrCokobBKFciY%2BWPLQvSoHorLBpx3%2FAKEngowqpyFYVEai0xbnw0LGMJf5I5LvG3AVkXrVklyVjwkAWvd6CU27EpO%2BFi5SWftlGKn0QsTdKEcUl2WJX5bmwBqfQh88ImNetezqvuqxck0YaeZDRX0LZraSHKkLQjj2PfKTNUMF2RRnFUVV6yMh6gecjMlINSfAzxySMqsVzc%3D' -H 'Host: audio-dc6-t1-1-v4v6.pandora.com' -H 'User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.12; rv:56.0) Gecko/20100101 Firefox/56.0' -H 'Accept: audio/webm,audio/ogg,audio/wav,audio/*;q=0.9,application/ogg;q=0.7,video/*;q=0.6,*/*;q=0.5' -H 'Accept-Language: en-US,en;q=0.5' -H 'Referer: https://www.pandora.com/station/play/3614121393881410450' -H 'Range: bytes=1196447-' -H 'Cookie: v2regbstage=true; at=w+4JR9QV/A586fLmbTRHODb2DtdNLz3iv9lfyPmlr8BZYBBuTkOUMfuVQGVqrgZtZ06p8aU9GI2MvP4oVCACHyL5o7cJLN5i/; v3ad=1:0:0:00000::0:0:0:0:::::0:0:0:0:0:1; pwc-2016=true; csrftoken=166fc33ba9dc1f13; _sl_path=/station/play/3614121393881410450' -H 'Connection: keep-alive' -H 'Pragma: no-cache' -H 'Cache-Control: no-cache'

And here is a similar Curl version of one which is fine:

curl 'https://audio-ch1-t1-2-v4v6.pandora.com/access/?version=5&lid=1634790290&token=baj4XMjHcK6Lq4eiHSI%2FDOqfXT%2Bkr3uSZ4S2UrcjPoio5J%2B2c6tDDU68kX0pNXYGaTjOTUQd%2Bf2V02IROUJEKdT9Ny17JEUHoz%2FJNnKQ7HpFuTVYrkOu8hNfsIcIs7D6igZzpandnuziF9kPwzMNQKaeNJudc9ue4%2F5iuEZ4jlt4iXjfzJN0DeN6cmg%2Fv%2F4x3I6U7g7D7L83MuUr4PSjjKdUnLzNm8PlwgBWxhhWUtamV6rqiBdOO4i9mNYaTA3iVujJ8PLUniNIxE%2Bk1129hRPWH3KV88c1EcIQ94sSnTiscb4LUSIG2eD6rFtoSaUSufPhBihr%2BKU%3D' -H 'Host: audio-ch1-t1-2-v4v6.pandora.com' -H 'User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.12; rv:56.0) Gecko/20100101 Firefox/56.0' -H 'Accept: audio/webm,audio/ogg,audio/wav,audio/*;q=0.9,application/ogg;q=0.7,video/*;q=0.6,*/*;q=0.5' -H 'Accept-Language: en-US,en;q=0.5' -H 'Referer: https://www.pandora.com/station/play/3614121393881410450' -H 'Range: bytes=0-' -H 'Cookie: v2regbstage=true; at=w+4JR9QV/A586fLmbTRHODb2DtdNLz3iv9lfyPmlr8BZYBBuTkOUMfuVQGVqrgZtZ06p8aU9GI2MvP4oVCACHyL5o7cJLN5i/; v3ad=1:0:0:00000::0:0:0:0:::::0:0:0:0:0:1; pwc-2016=true; csrftoken=a89d062674f6a593; _sl_path=/station/play/3614121393881410450' -H 'Connection: keep-alive' -H 'Pragma: no-cache' -H 'Cache-Control: no-cache'

The bad request works when I change the Range value to "1196446-" instead (one byte less), indicating that it may be an off-by-one issue, or something similar. Likewise, changing the Range on the "good" request to a large enough value triggers the same 400 response.

But it's tough to gauge what the scripts are doing to make the requests out-of-range, or why the error handling isn't stopping playback of the existing Audio context before starting a new one in this case.

Mike, do you think this would be enough for outreach?

Comment 18

[Mike Taylor [:miketaylr] (62 Regression Engineering Owner)]

Thanks Thomas!

Dragana, comment #17, does anything jump out at you that's HTTP/network related from the mozregression range that might be related:

https://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=0b255199db9d6a6f189b89b7906f99155bde3726&tochange=b9bd73036a925e44f44ee87e779fbbdb2dbe618c

Comment 19

[Thomas Wisniewski]

I just did a by-ear regression range narrowing and got this result:

https://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=0b255199db9d6a6f189b89b7906f99155bde3726&tochange=37a5b7f6f101df2eb292b1b6baaf1540c9920e20

Unfortunately it couldn't find any build urls for the changesets in that range :(

Comment 20

[Frost]

I am experiencing the same problems with Pandora on the Nightly browser. Man am I glad I found you guys. I thought I might be alone on this one.

Comment 21

[Dragana Damjanovic [:dragana]]

(In reply to Mike Taylor [:miketaylr] (55 Regression Engineering Owner) from comment #18)
> Thanks Thomas!
> 
> Dragana, comment #17, does anything jump out at you that's HTTP/network
> related from the mozregression range that might be related:
> 
> https://hg.mozilla.org/mozilla-central/
> pushloghtml?fromchange=0b255199db9d6a6f189b89b7906f99155bde3726&tochange=b9bd
> 73036a925e44f44ee87e779fbbdb2dbe618c

This does not look like a networking problem.
Can you make a http log, so I can see what is happeing in necko?

https://developer.mozilla.org/en-US/docs/Mozilla/Debugging/HTTP_logging
and use MOZ_LOG=timestamp,nsHttp:5

Comment 22

[Mike Taylor [:miketaylr] (62 Regression Engineering Owner)]

Tom, can you attach an http log?

Comment 23

[Thomas Wisniewski]

Sure. I managed to get a log, but it's 6 megs (even zipped). Here's a link to it on my own server: http://thomas.tanrei.ca/moz/network-log.zip

Note that it's near the end of the log that the bug manifested and the song started playing twice, when the console reported accesses to:

GET https://ml314.com/imsync.ashx
GET https://audio-sv5-t1-2-v4v6.pandora.com/access/ [HTTP/1.1 400 Bad Request 427ms] 
GET https://ml314.com/imsync.ashx

Comment 24

[Dragana Damjanovic [:dragana]]

(In reply to Thomas Wisniewski from comment #23)
> Sure. I managed to get a log, but it's 6 megs (even zipped). Here's a link
> to it on my own server: http://thomas.tanrei.ca/moz/network-log.zip
> 
> Note that it's near the end of the log that the bug manifested and the song
> started playing twice, when the console reported accesses to:
> 
> GET https://ml314.com/imsync.ashx
> GET https://audio-sv5-t1-2-v4v6.pandora.com/access/ [HTTP/1.1 400 Bad
> Request 427ms] 
> GET https://ml314.com/imsync.ashx

thanks for the log.

Something outside necko is setting this header. I do not know who.

The first request returns:
2017-06-14 15:58:45.092277 UTC - [Socket Thread]: I/nsHttp   HTTP/1.1 206 Partial Content
2017-06-14 15:58:45.092278 UTC - [Socket Thread]: I/nsHttp   Date: Wed, 14 Jun 2017 15:58:45 GMT
2017-06-14 15:58:45.092329 UTC - [Socket Thread]: I/nsHttp   Server: Apache
2017-06-14 15:58:45.092332 UTC - [Socket Thread]: I/nsHttp   Content-Range: bytes 0-2071208/2071209
2017-06-14 15:58:45.092334 UTC - [Socket Thread]: I/nsHttp   Content-Length: 2071209
...

which is actually the whole resource (Content-Range: bytes 0-2071208/2071209 the last number is size of the resource)

Something outside necko makes a new request and sets header Range: bytes=2071209-

Comment 25

[Thomas Wisniewski]

Interestingly, I can't reproduce this anymore on today's nightly (and neither could Mike Taylor). However, I can still reproduce it with a build from a couple weeks ago, so I did a mozregression to try to find what might have fixed it. Unfortunately it didn't isolate the fix, and I'm not sure what in the range (if anything) would be the likely fix:

>No more inbound revisions, bisection finished.
>First good revision: 228504fdc6e9e3daea55c61ccd13cff1a8469ec6
>Last bad revision: 416c3c8c4b3db9ba96a103ce7820c9a140a3051d
>Pushlog:
>https://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=416c3c8c4b3db9ba96a103ce7820c9a140a3051d&tochange=228504fdc6e9e3daea55c61ccd13cff1a8469ec6
>
>************* Switching to autoland by process of elimination (no branch detected in commit message)
>Getting autoland builds between 2cf23132f3b1aba5ed6cfcd2b9cdaabb5cccc0f5 and 228504fdc6e9e3daea55c61ccd13cff1a8469ec6
>ERROR: The url u'https://hg.mozilla.org/integration/autoland/json-pushes?fromchange=228504fdc6e9e3daea55c61ccd13cff1a8469ec6&tochange=2cf23132f3b1aba5ed6cfcd2b9cdaabb5cccc0f5' contains no pushlog. Maybe use another range ?

Dragana, might anything in that range stand out as being related to this issue?

Comment 26

[Nicholas Nethercote [:njn]]

I can confirm that this is fixed for me in Nightly! I was running a Nightly that had a pending update. Before doing the update I tested Pandora and I reproduced the bug. I then triggered the update and I can no longer reproduce the bug.

Here are the revisions from about:buildconfig:

Bad:  https://hg.mozilla.org/mozilla-central/rev/95543bdc59bd038a3d5d084b85a4fec493c349ee
Good: https://hg.mozilla.org/mozilla-central/rev/7a6baa6cca3292e8099e652b64d27e74df560874

This gives the following regression range:

https://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=95543bdc59bd038a3d5d084b85a4fec493c349ee&tochange=7a6baa6cca3292e8099e652b64d27e74df560874

Comment 27

[Shian-Yow Wu [:swu]]

(In reply to Thomas Wisniewski from comment #25)
> >************* Switching to autoland by process of elimination (no branch detected in commit message)
> >Getting autoland builds between 2cf23132f3b1aba5ed6cfcd2b9cdaabb5cccc0f5 and 228504fdc6e9e3daea55c61ccd13cff1a8469ec6
> >ERROR: The url u'https://hg.mozilla.org/integration/autoland/json-pushes?fromchange=228504fdc6e9e3daea55c61ccd13cff1a8469ec6&tochange=2cf23132f3b1aba5ed6cfcd2b9cdaabb5cccc0f5' contains no pushlog. Maybe use another range ?

No pushlog in this range because the tochange was landed earlier than the fromchange in autoland, which is in different order from mozilla-central.  If the regression is within this range, let's reverse the two revisions and explicitly asking mozregression to use autoland repo?

$ mozregression --repo autoland --find-fix -b 2cf23132f3b1aba5ed6cfcd2b9cdaabb5cccc0f5 -g 228504fdc6e9e3daea55c61ccd13cff1a8469ec6

Comment 28

[Shian-Yow Wu [:swu]]

According to the regression range in comment 19 and the fixed range in comment 26, bug 1319111 is in both of them.  Not sure if it's related.

Comment 29

[Thomas Wisniewski]

With :swu's great tip in comment 27 (thanks!), I got this result:

>INFO: First good revision: d1adec83acac5da5f6037a88a13d83eec1b88980
>INFO: Last bad revision: f4a46277935b2702c2a0351204233adb9d7bb3df
>INFO: Pushlog:
>https://hg.mozilla.org/integration/autoland/pushloghtml?fromchange=f4a46277935b2702c2a0351204233adb9d7bb3df&tochange=d1adec83acac5da5f6037a88a13d83eec1b88980

That is, bug 1374475.

But I'm tired now, so I'll try an m-c build with that patch reverted tomorrow :)

Comment 30

[Jean-Yves Avenard [:jya]]

Note that the issue in bug 1373618, is the server reporting Range-Request at first, yet fail when we seek.

Is Pandora having the same issue?

It should be fixed in bug 1374475, but only if the MP3 file is less than 8MB in size. The issue will occur for bigger file if the server incorrectly reports capabilities.

Comment 31

[Dragana Damjanovic [:dragana]]

Bug 1374475 is a work around this problem. If the file on Pandora would be bigger or we change our Media-Cache-Size the problem will appear again.

in dom/media/MediaResource.cpp we are setting up a new channel and setting request headers as well. Somewhere there we should add a check so that we do not request data that is out of range for a resource (in comment 24 the size of the resource was 2071209 and then we request range '2071209-').

Having two streams playing sounds like a bug probably in MediaResource.cpp

Can someone familiar with this code take a look, we should fix this properly?

Comment 32

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

(In reply to Dragana Damjanovic [:dragana] from comment #31)
> Having two streams playing sounds like a bug probably in MediaResource.cpp
Which 2 steams do you mean?

Comment 33

[Jean-Yves Avenard [:jya]]

(In reply to Dragana Damjanovic [:dragana] from comment #31)
> Bug 1374475 is a work around this problem. If the file on Pandora would be
> bigger or we change our Media-Cache-Size the problem will appear again.

only if Pandora server reports support for range request, but actually does not.

> 
> in dom/media/MediaResource.cpp we are setting up a new channel and setting
> request headers as well. Somewhere there we should add a check so that we do
> not request data that is out of range for a resource (in comment 24 the size
> of the resource was 2071209 and then we request range '2071209-').
> 
> Having two streams playing sounds like a bug probably in MediaResource.cpp
> 
> Can someone familiar with this code take a look, we should fix this properly?

It's not a bug of MediaResource per say. We download up to 30s of data ahead of currentTime. After which the download is suspended.

When download is resumed, it can either continue as-is, or it needs to seek where it stopped (but only if seeking was reported as supported by the server, otherwise it redownload from 0).

The issue occurs when seeking was reported as supported, yet when we attempt to do so, it doesn't.
This is then treated as EOS.

Comment 34

[Thomas Wisniewski]

For the record, I just confirmed that commenting out the code from the patch in bug 1374475 does indeed cause the problem to manifest. There is also a debug message in stdout that I had missed before which pops up when the error happens:

>[Child 75097] WARNING: Decoder=11b887800 state=SEEKING Audio not synced after seek, maybe a poorly muxed file?: file dom/media/MediaDecoderStateMachine.cpp, line 1375

However, :jya, their server does support Range requests (I just double-checked). It just returns a 400 response when the range is from past the end of the file, which is what Firefox seems to end up sending, as per comment 17.

Comment 35

[Jean-Yves Avenard [:jya]]

Hmmm... I can see why.

We can't rely on the MediaResource's length as it typically changes over time, in particular live streaming...

The MP3Demuxer reads until it fails and then treats it at as EOS....
why would that start another stream however... we aren't the one starting a 2nd audio stream, pandora must be handling some particular events thinking it's all done, when it's not.

Comment 36

[Jean-Yves Avenard [:jya]]

(In reply to Thomas Wisniewski from comment #34)
> debug message in stdout that I had missed before which pops up when the
> error happens:
> 
> >[Child 75097] WARNING: Decoder=11b887800 state=SEEKING Audio not synced after seek, maybe a poorly muxed file?: file dom/media/MediaDecoderStateMachine.cpp, line 1375
> 

This is irrelevant for an audio only file. There's no A/V sync to worry about.

It only means that when we seek to currentTime=t ; we end up slightly ahead of t , which isn't surprising as seeking in an MP3 is a highly estimated affairs.

Comment 37

[Jean-Yves Avenard [:jya]]

(In reply to Thomas Wisniewski from comment #34)

> However, :jya, their server does support Range requests (I just
> double-checked). It just returns a 400 response when the range is from past
> the end of the file, which is what Firefox seems to end up sending, as per
> comment 17.

Requesting past the range request should be okay (as I wrote, typically the Content-Length is a moving target on many server).

Does it ignore completely the request and return 400, or return at least all the data from the beginning of the range to the existing length?

if not the latter, that IMHO is the wrong behaviour on this server.

Comment 38

[Thomas Wisniewski]

It gives a 400 if you request a range that starts past the end of the file, or the range is nonsensical.

These requests work (for a file that's under 100000000 bytes long):
  Range: bytes=0-
  Range: bytes=0-100000000
  Range: bytes=1000-100000000

These do not work, they give a 400 response:
  Range: bytes=10000000-
  Range: bytes=10000000-10000001
  Range: bytes=2000-1000

Comment 39

[Jean-Yves Avenard [:jya]]

but what about 1000-200000000?

Comment 40

[Thomas Wisniewski]

Yes that works fine, like the third case I listed above.

Comment 41

[Nicholas Nethercote [:njn]]

(In reply to Nicholas Nethercote [:njn] from comment #26)
> I can confirm that this is fixed for me in Nightly!

Actually, I just hit it again. But that was after listening for a couple of hours. It's certainly happening *much* less frequently.

Comment 42

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

Can't repro the issue on Mac. It says "Please ensure you are using the latest Flash Player". Can't repro the issue on Linux either where audio elements are used.

Comment 43

[Chris Pearce (:cpearce)]

I hit this issue yesterday, and I think my Nightly was up-to-date enough to include the fix for bug 1373618. I will try again today with a fully update Nightly and logging enabled.

The patch in bug 1373618 should make us not request after the end of the resource when recovering from suspending the download. We shouldn't be suspending the download if the Content-Length is less than 8MB now that bug 1374475 is in Nightly.

Ideally, the server should respond with a 416 response when we request after the end of the resource.

Comment 44

[Mike Taylor [:miketaylr] (62 Regression Engineering Owner)]

Just listened for 1.5 hours and didn't hit the bug, but we've had a few recent webcompat reports so it's still out there for some people it seems.

Comment 45

[Chris Pearce (:cpearce)]

I've been listening for several multi-hour sessions and I haven't hit the bug again. So bug 1374475 may have fixed or worked around it.

Comment 46

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

Per comment 45, let's have QA to verify on 55.

Comment 47

[Marcia Knous [:marcia - needinfo? me]]

ni on Andrei for verification since we are getting close to the end of the 55 cycle.

Comment 48

[Ciprian Georgiu [:ciprian_georgiu], Release Desktop QA]

(In reply to Marcia Knous [:marcia - use ni] from comment #47)
> ni on Andrei for verification since we are getting close to the end of the
> 55 cycle.

Hi,

I reproduced this issue on Nightly 55.0a1 (2017-05-12) using STR from comment 0.
This is not reproducible anymore on 55.0b11 (20170720101430) using Windows 10 x64 and Mac OS X 10.11.5.

I had some issues, unfortunately with my VPN proxy on Ubuntu 16.04 (I've used VPN - Hola due to country restrictions), the pandora's website didn't load every time, or when it eventually loaded, it took up to 10 minutes. So, I cannot properly verify and confirm if this issue is fixed or not on Ubuntu.

Please let me know if I can help with more info!

Comment 49

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

Ciprian,
Thanks for your testing. 

Mike, 
Can someone in your team living in USA help test it on Ubuntu and see if those web compat issues are gone as well?

Comment 50

[Mike Taylor [:miketaylr] (62 Regression Engineering Owner)]

Sure thing, I'll fire up Ubuntu now and see if I can reproduce there.

Comment 51

[Mike Taylor [:miketaylr] (62 Regression Engineering Owner)]

Adam Stevenson just verified that the issue appears to be fixed in Nightly on Ubuntu. So... let's close as FIXED.

(If there's reasons for it to stay open, apologies, just re-open).

Comment 52

[Ciprian Georgiu [:ciprian_georgiu], Release Desktop QA]

I will mark this as verified fixed per comment 48 and comment 51.