Skip to content
This repository has been archived by the owner on Dec 7, 2020. It is now read-only.

Randomly stops playing after few minutes #161

Closed
wf1nder opened this issue Dec 24, 2016 · 105 comments
Closed

Randomly stops playing after few minutes #161

wf1nder opened this issue Dec 24, 2016 · 105 comments

Comments

@wf1nder
Copy link

wf1nder commented Dec 24, 2016

Can’t get gmusic plugin to work normally. It starts playing, but after a some time (few minutes) randomly stops. There appears message on console:
ERROR GStreamer error: gst-resource-error-quark: Forbidden (15)

Switching to next track fixes problem for the next few minutes.
Tried on my Raspberry PI 1, Raspberry PI 2, Odroid C2, and on PC. Distros: Ubuntu, Debian, Raspbian, Volumio, Ubuntu on C2. Tried on 3 diffirent USB dacs, and on I2S dac. Also, mopidy was installed from deb-repo, or from pip. In all cases problem appears.
Now using last versions of mopidy and mopidy from pip: mopidy=2.0.1, mopidy-gmusic=2.0.0. Also, gstreamer1.0.

@fgtham
Copy link

fgtham commented Jan 2, 2017

Same here, sample debug output:

DEBUG    2017-01-02 11:54:24,501 [17253:HttpServer] mopidy.http.handlers Received WebSocket message from 127.0.0.1: u'{"method":"core.playback.get_time_position","jsonrpc":"2.0","id":445}'
DEBUG    2017-01-02 11:54:24,503 [17253:HttpServer] mopidy.http.handlers Sent WebSocket message to 127.0.0.1: '{"jsonrpc": "2.0", "id": 445, "result": 419113}'
DEBUG    2017-01-02 11:54:25,502 [17253:HttpServer] mopidy.http.handlers Received WebSocket message from 127.0.0.1: u'{"method":"core.playback.get_time_position","jsonrpc":"2.0","id":446}'
DEBUG    2017-01-02 11:54:25,504 [17253:HttpServer] mopidy.http.handlers Sent WebSocket message to 127.0.0.1: '{"jsonrpc": "2.0", "id": 446, "result": 420113}'
DEBUG    2017-01-02 11:54:26,356 [17253:MainThread] mopidy.audio.gst Got ERROR bus message: error=u'gst-resource-error-quark: Forbidden (15)' debug=u'/var/tmp/portage/media-plugins/gst-plugins-soup-1.8.3/work/gst-plugins-good-1.8.3/ext/soup/gstsouphttpsrc.c(1634): gst_soup_http_src_parse_status (): /GstPlayBin:playbin0/GstURIDecodeBin:uridecodebin0/GstSoupHTTPSrc:source:\nForbidden (403), URL: https://r5---sn-4g57knd6.c.doc-0-0-sj.sj.googleusercontent.com/videoplayback?id=<...>&itag=25&source=skyjam&begin=0&upn=IXy4QPnlE-g&o=<...>&cmbypass=yes&ratebypass=yes&ip=<...>&ipbits=0&expire=1483354133&sparams=cmbypass,expire,id,ip,ipbits,itag,mm,mn,ms,mv,nh,o,pl,ratebypass,source,upn&signature=<...>&key=cms1&mm=31&mn=sn-4g57knd6&ms=au&mt=1483353727&mv=m&nh=<...>&pl=22, Redirect to: (NULL)'
ERROR    2017-01-02 11:54:26,357 [17253:MainThread] mopidy.audio.gst GStreamer error: gst-resource-error-quark: Forbidden (15)
DEBUG    2017-01-02 11:54:26,363 [17253:MainThread] mopidy.audio.gst Changing state to GST_STATE_NULL: result=GST_STATE_CHANGE_SUCCESS
$ mopidy deps
Executable: /home/flo/bin/mopidy
Platform: Linux-4.9.0-gentoo-x86_64-Intel-R-_Core-TM-_i5-4570_CPU_@_3.20GHz-with-gentoo-2.3
Python: CPython 2.7.12 from /usr/lib64/python2.7
Mopidy: 2.0.1 from /home/flo/.local/lib64/python2.7/site-packages
  tornado>=2.3: 4.4.2 from /usr/lib64/python2.7/site-packages
    singledispatch: 3.4.0.3 from /usr/lib64/python2.7/site-packages
      six: 1.10.0 from /usr/lib64/python2.7/site-packages
    certifi: 2016.9.26 from /usr/lib64/python2.7/site-packages
    backports_abc>=0.4: 0.5 from /home/flo/.local/lib64/python2.7/site-packages
  requests>=2.0: 2.12.4 from /usr/lib64/python2.7/site-packages
  Pykka>=1.1: 1.2.1 from /home/flo/.local/lib64/python2.7/site-packages
  setuptools: 32.3.1 from /home/flo/.local/lib64/python2.7/site-packages
Mopidy-MusicBox-Webclient: 2.3.0 from /home/flo/.local/lib64/python2.7/site-packages
  Mopidy>=1.1.0: 2.0.1 from /home/flo/.local/lib64/python2.7/site-packages
    tornado>=2.3: 4.4.2 from /usr/lib64/python2.7/site-packages
      singledispatch: 3.4.0.3 from /usr/lib64/python2.7/site-packages
        six: 1.10.0 from /usr/lib64/python2.7/site-packages
      certifi: 2016.9.26 from /usr/lib64/python2.7/site-packages
      backports_abc>=0.4: 0.5 from /home/flo/.local/lib64/python2.7/site-packages
    requests>=2.0: 2.12.4 from /usr/lib64/python2.7/site-packages
    Pykka>=1.1: 1.2.1 from /home/flo/.local/lib64/python2.7/site-packages
    setuptools: 32.3.1 from /home/flo/.local/lib64/python2.7/site-packages
  setuptools: 32.3.1 from /home/flo/.local/lib64/python2.7/site-packages
Mopidy-Moped: 0.7.0 from /home/flo/.local/lib64/python2.7/site-packages
  setuptools: 32.3.1 from /home/flo/.local/lib64/python2.7/site-packages
  Mopidy>=1.0.0: 2.0.1 from /home/flo/.local/lib64/python2.7/site-packages
    tornado>=2.3: 4.4.2 from /usr/lib64/python2.7/site-packages
      singledispatch: 3.4.0.3 from /usr/lib64/python2.7/site-packages
        six: 1.10.0 from /usr/lib64/python2.7/site-packages
      certifi: 2016.9.26 from /usr/lib64/python2.7/site-packages
      backports_abc>=0.4: 0.5 from /home/flo/.local/lib64/python2.7/site-packages
    requests>=2.0: 2.12.4 from /usr/lib64/python2.7/site-packages
    Pykka>=1.1: 1.2.1 from /home/flo/.local/lib64/python2.7/site-packages
    setuptools: 32.3.1 from /home/flo/.local/lib64/python2.7/site-packages
Mopidy-GMusic: 2.0.0 from /home/flo/.local/lib64/python2.7/site-packages
  setuptools: 32.3.1 from /home/flo/.local/lib64/python2.7/site-packages
  Pykka>=1.1: 1.2.1 from /home/flo/.local/lib64/python2.7/site-packages
  cachetools>=1.0: 2.0.0 from /home/flo/.local/lib64/python2.7/site-packages
  Mopidy>=1.0: 2.0.1 from /home/flo/.local/lib64/python2.7/site-packages
    tornado>=2.3: 4.4.2 from /usr/lib64/python2.7/site-packages
      singledispatch: 3.4.0.3 from /usr/lib64/python2.7/site-packages
        six: 1.10.0 from /usr/lib64/python2.7/site-packages
      certifi: 2016.9.26 from /usr/lib64/python2.7/site-packages
      backports_abc>=0.4: 0.5 from /home/flo/.local/lib64/python2.7/site-packages
    requests>=2.0: 2.12.4 from /usr/lib64/python2.7/site-packages
    Pykka>=1.1: 1.2.1 from /home/flo/.local/lib64/python2.7/site-packages
    setuptools: 32.3.1 from /home/flo/.local/lib64/python2.7/site-packages
  gmusicapi>=10.1: 10.1.0 from /home/flo/.local/lib64/python2.7/site-packages
    validictory!=0.9.2,>=0.8.0: 1.1.0 from /home/flo/.local/lib64/python2.7/site-packages
    decorator>=3.3.1: 4.0.2 from /usr/lib64/python2.7/site-packages
    mutagen>=1.34: 1.36 from /home/flo/.local/lib64/python2.7/site-packages
    requests!=1.2.0,!=2.2.1,!=2.8.0,!=2.8.1,>=1.1.0: 2.12.4 from /usr/lib64/python2.7/site-packages
    python-dateutil!=2.0,>=1.3: 2.4.2 from /usr/lib64/python2.7/site-packages
      six>=1.5: 1.10.0 from /usr/lib64/python2.7/site-packages
    proboscis>=1.2.5.1: 1.2.6.0 from /home/flo/.local/lib64/python2.7/site-packages
    protobuf>=3.0.0: 3.1.0.post1 from /home/flo/.local/lib64/python2.7/site-packages
      six>=1.9: 1.10.0 from /usr/lib64/python2.7/site-packages
      setuptools: 32.3.1 from /home/flo/.local/lib64/python2.7/site-packages
    oauth2client>=1.1: 2.0.1 from /usr/lib64/python2.7/site-packages
      httplib2>=0.9.1: 0.9.2 from /usr/lib64/python2.7/site-packages
      pyasn1>=0.1.7: 0.1.8 from /usr/lib64/python2.7/site-packages
      pyasn1-modules>=0.0.5: 0.0.5 from /usr/lib64/python2.7/site-packages
        pyasn1>=0.1.4: 0.1.8 from /usr/lib64/python2.7/site-packages
      rsa>=3.1.4: 3.2.3 from /usr/lib64/python2.7/site-packages
        pyasn1>=0.1.3: 0.1.8 from /usr/lib64/python2.7/site-packages
      six>=1.6.1: 1.10.0 from /usr/lib64/python2.7/site-packages
    mock>=0.7.0: 2.0.0 from /home/flo/.local/lib64/python2.7/site-packages
      funcsigs>=1; python_version < "3.3": 1.0.2 from /home/flo/.local/lib64/python2.7/site-packages
      six>=1.9: 1.10.0 from /usr/lib64/python2.7/site-packages
      pbr>=0.11: 1.10.0 from /usr/lib64/python2.7/site-packages
    appdirs>=1.1.0: 1.4.0 from /home/flo/.local/lib64/python2.7/site-packages
    gpsoauth>=0.2.0: 0.4.0 from /home/flo/.local/lib64/python2.7/site-packages
      pycryptodomex>=3.0: 3.4.3 from /home/flo/.local/lib64/python2.7/site-packages
      requests: 2.12.4 from /usr/lib64/python2.7/site-packages
    MechanicalSoup>=0.4.0: 0.6.0 from /home/flo/.local/lib64/python2.7/site-packages
      requests>=2.0: 2.12.4 from /usr/lib64/python2.7/site-packages
      beautifulsoup4: 4.5.1 from /home/flo/.local/lib64/python2.7/site-packages
      six>=1.4: 1.10.0 from /usr/lib64/python2.7/site-packages
    six>=1.9.0: 1.10.0 from /usr/lib64/python2.7/site-packages
    future: 0.16.0 from /home/flo/.local/lib64/python2.7/site-packages
  requests>=2.0: 2.12.4 from /usr/lib64/python2.7/site-packages
GStreamer: 1.8.3.0 from /usr/lib64/python2.7/site-packages/gi
  Detailed information: 
    Python wrapper: python-gi 3.20.1
    Relevant elements:
      Found:
        uridecodebin
        souphttpsrc
        appsrc
        alsasink
        pulsesink
        id3demux
        lamemp3enc
        mad
        mpegaudioparse
        mpg123audiodec
        vorbisdec
        vorbisenc
        vorbisparse
        oggdemux
        oggmux
        oggparse
        flacparse
      Not found:
        osssink
        oss4sink
        flump3dec
        id3v2mux
        flacdec
        shout2send

@fgtham
Copy link

fgtham commented Jan 2, 2017

Issue seems to be on Google's side. With the server returning HTTP 403, there's not much one can do.

@belak
Copy link
Contributor

belak commented Jan 2, 2017

Grabbing the whole track at once would probably fix the issue but that's not as simple as it should be.

@ghost
Copy link

ghost commented Mar 15, 2017

@wf1nder Can you try a different gstreamer package and let us know? I removed gstreamer0.10-0.10.36-16 and it seems to have cleared up the problem. The extension has always worked for me in the past before I started tinkering with my gstreamer plugins recently.

@marcik4
Copy link

marcik4 commented Mar 23, 2017

This issue started to happen for me in last few weeks - it was working stable before. Didn't update gstreamer.

@xtedy
Copy link

xtedy commented Mar 25, 2017

I have this problem too. I dont make any update

ERROR    GStreamer error: gst-resource-error-quark: Forbidden (15)
ERROR    GStreamer error: gst-resource-error-quark: Forbidden (15)
ERROR    GStreamer error: gst-resource-error-quark: Forbidden (15)
Executable: /usr/bin/mopidy
Platform: Linux-3.10.0-514.10.2.el7.x86_64-x86_64-with-centos-7.3.1611-Core
Python: CPython 2.7.5 from /usr/lib64/python2.7
Mopidy: 2.0.1 from /usr/lib/python2.7/site-packages
  setuptools: 28.8.0 from /usr/lib/python2.7/site-packages
  Pykka>=1.1: 1.2.1 from /usr/lib/python2.7/site-packages
  requests>=2.0: 2.12.1 from /usr/lib/python2.7/site-packages
  tornado>=2.3: 4.4.2 from /usr/lib64/python2.7/site-packages
    backports.ssl_match_hostname: 3.5.0.1 from /usr/lib/python2.7/site-packages
    singledispatch: 3.4.0.3 from /usr/lib/python2.7/site-packages
      six: 1.10.0 from /usr/lib/python2.7/site-packages
    certifi: 2016.9.26 from /usr/lib/python2.7/site-packages
    backports_abc>=0.4: 0.5 from /usr/lib/python2.7/site-packages
Mopidy-GMusic: 2.0.0 from /usr/lib64/python2.7/site-packages
  cachetools>=1.0: 2.0.0 from /usr/lib/python2.7/site-packages
  Pykka>=1.1: 1.2.1 from /usr/lib/python2.7/site-packages
  requests>=2.0: 2.12.1 from /usr/lib/python2.7/site-packages
  setuptools: 28.8.0 from /usr/lib/python2.7/site-packages
  gmusicapi>=10.1: 10.1.0 from /usr/lib/python2.7/site-packages
    validictory!=0.9.2,>=0.8.0: 1.1.0 from /usr/lib/python2.7/site-packages
    decorator>=3.3.1: 4.0.10 from /usr/lib/python2.7/site-packages
    mutagen>=1.34: 1.35.1 from /usr/lib/python2.7/site-packages
    requests!=1.2.0,!=2.2.1,!=2.8.0,!=2.8.1,>=1.1.0: 2.12.1 from /usr/lib/python2.7/site-packages
    python-dateutil!=2.0,>=1.3: 2.6.0 from /usr/lib/python2.7/site-packages
      six>=1.5: 1.10.0 from /usr/lib/python2.7/site-packages
    proboscis>=1.2.5.1: 1.2.6.0 from /usr/lib/python2.7/site-packages
    protobuf>=3.0.0: 3.1.0.post1 from /usr/lib/python2.7/site-packages
      setuptools: 28.8.0 from /usr/lib/python2.7/site-packages
      six>=1.9: 1.10.0 from /usr/lib/python2.7/site-packages
    oauth2client>=1.1: 4.0.0 from /usr/lib/python2.7/site-packages
      six>=1.6.1: 1.10.0 from /usr/lib/python2.7/site-packages
      pyasn1>=0.1.7: 0.1.9 from /usr/lib/python2.7/site-packages
      pyasn1-modules>=0.0.5: 0.0.8 from /usr/lib/python2.7/site-packages
        pyasn1>=0.1.8: 0.1.9 from /usr/lib/python2.7/site-packages
      rsa>=3.1.4: 3.4.2 from /usr/lib/python2.7/site-packages
        pyasn1>=0.1.3: 0.1.9 from /usr/lib/python2.7/site-packages
      httplib2>=0.9.1: 0.9.2 from /usr/lib/python2.7/site-packages
    mock>=0.7.0: 2.0.0 from /usr/lib/python2.7/site-packages
      funcsigs>=1; python_version < "3.3": 1.0.2 from /usr/lib/python2.7/site-packages
      pbr>=0.11: 1.10.0 from /usr/lib/python2.7/site-packages
      six>=1.9: 1.10.0 from /usr/lib/python2.7/site-packages
    appdirs>=1.1.0: 1.4.0 from /usr/lib/python2.7/site-packages
    gpsoauth>=0.2.0: 0.4.0 from /usr/lib/python2.7/site-packages
      pycryptodomex>=3.0: 3.4.3 from /usr/lib64/python2.7/site-packages
      requests: 2.12.1 from /usr/lib/python2.7/site-packages
    MechanicalSoup>=0.4.0: 0.6.0 from /usr/lib/python2.7/site-packages
      six>=1.4: 1.10.0 from /usr/lib/python2.7/site-packages
      requests>=2.0: 2.12.1 from /usr/lib/python2.7/site-packages
      beautifulsoup4: 4.5.1 from /usr/lib/python2.7/site-packages
    six>=1.9.0: 1.10.0 from /usr/lib/python2.7/site-packages
    future: 0.16.0 from /usr/lib/python2.7/site-packages
  Mopidy>=1.0: 2.0.1 from /usr/lib/python2.7/site-packages
    setuptools: 28.8.0 from /usr/lib/python2.7/site-packages
    Pykka>=1.1: 1.2.1 from /usr/lib/python2.7/site-packages
    requests>=2.0: 2.12.1 from /usr/lib/python2.7/site-packages
    tornado>=2.3: 4.4.2 from /usr/lib64/python2.7/site-packages
      backports.ssl_match_hostname: 3.5.0.1 from /usr/lib/python2.7/site-packages
      singledispatch: 3.4.0.3 from /usr/lib/python2.7/site-packages
        six: 1.10.0 from /usr/lib/python2.7/site-packages
      certifi: 2016.9.26 from /usr/lib/python2.7/site-packages
      backports_abc>=0.4: 0.5 from /usr/lib/python2.7/site-packages
Mopidy-MusicBox-Webclient: 2.3.0 from /usr/lib/python2.7/site-packages
  setuptools: 28.8.0 from /usr/lib/python2.7/site-packages
  Mopidy>=1.1.0: 2.0.1 from /usr/lib/python2.7/site-packages
    setuptools: 28.8.0 from /usr/lib/python2.7/site-packages
    Pykka>=1.1: 1.2.1 from /usr/lib/python2.7/site-packages
    requests>=2.0: 2.12.1 from /usr/lib/python2.7/site-packages
    tornado>=2.3: 4.4.2 from /usr/lib64/python2.7/site-packages
      backports.ssl_match_hostname: 3.5.0.1 from /usr/lib/python2.7/site-packages
      singledispatch: 3.4.0.3 from /usr/lib/python2.7/site-packages
        six: 1.10.0 from /usr/lib/python2.7/site-packages
      certifi: 2016.9.26 from /usr/lib/python2.7/site-packages
      backports_abc>=0.4: 0.5 from /usr/lib/python2.7/site-packages
Mopidy-Mopify: 1.6.0 from /usr/lib/python2.7/site-packages
  setuptools: 28.8.0 from /usr/lib/python2.7/site-packages
  Mopidy>=0.19: 2.0.1 from /usr/lib/python2.7/site-packages
    setuptools: 28.8.0 from /usr/lib/python2.7/site-packages
    Pykka>=1.1: 1.2.1 from /usr/lib/python2.7/site-packages
    requests>=2.0: 2.12.1 from /usr/lib/python2.7/site-packages
    tornado>=2.3: 4.4.2 from /usr/lib64/python2.7/site-packages
      backports.ssl_match_hostname: 3.5.0.1 from /usr/lib/python2.7/site-packages
      singledispatch: 3.4.0.3 from /usr/lib/python2.7/site-packages
        six: 1.10.0 from /usr/lib/python2.7/site-packages
      certifi: 2016.9.26 from /usr/lib/python2.7/site-packages
      backports_abc>=0.4: 0.5 from /usr/lib/python2.7/site-packages
  ConfigObj: 5.0.6 from /usr/lib/python2.7/site-packages
    six: 1.10.0 from /usr/lib/python2.7/site-packages
Mopidy-Moped: 0.7.0 from /usr/lib/python2.7/site-packages
  setuptools: 28.8.0 from /usr/lib/python2.7/site-packages
  Mopidy>=1.0.0: 2.0.1 from /usr/lib/python2.7/site-packages
    setuptools: 28.8.0 from /usr/lib/python2.7/site-packages
    Pykka>=1.1: 1.2.1 from /usr/lib/python2.7/site-packages
    requests>=2.0: 2.12.1 from /usr/lib/python2.7/site-packages
    tornado>=2.3: 4.4.2 from /usr/lib64/python2.7/site-packages
      backports.ssl_match_hostname: 3.5.0.1 from /usr/lib/python2.7/site-packages
      singledispatch: 3.4.0.3 from /usr/lib/python2.7/site-packages
        six: 1.10.0 from /usr/lib/python2.7/site-packages
      certifi: 2016.9.26 from /usr/lib/python2.7/site-packages
      backports_abc>=0.4: 0.5 from /usr/lib/python2.7/site-packages
Mopidy-Material-Webclient: 0.2.1 from /usr/lib/python2.7/site-packages
  setuptools: 28.8.0 from /usr/lib/python2.7/site-packages
  Mopidy>=1.0: 2.0.1 from /usr/lib/python2.7/site-packages
    setuptools: 28.8.0 from /usr/lib/python2.7/site-packages
    Pykka>=1.1: 1.2.1 from /usr/lib/python2.7/site-packages
    requests>=2.0: 2.12.1 from /usr/lib/python2.7/site-packages
    tornado>=2.3: 4.4.2 from /usr/lib64/python2.7/site-packages
      backports.ssl_match_hostname: 3.5.0.1 from /usr/lib/python2.7/site-packages
      singledispatch: 3.4.0.3 from /usr/lib/python2.7/site-packages
        six: 1.10.0 from /usr/lib/python2.7/site-packages
      certifi: 2016.9.26 from /usr/lib/python2.7/site-packages
      backports_abc>=0.4: 0.5 from /usr/lib/python2.7/site-packages
  wifi>=0.3.4: 0.3.4 from /usr/lib/python2.7/site-packages
    setuptools: 28.8.0 from /usr/lib/python2.7/site-packages
    pbkdf2: 1.3 from /usr/lib/python2.7/site-packages
GStreamer: 1.10.2.0 from /usr/lib64/python2.7/site-packages/gi
  Detailed information: 
    Python wrapper: python-gi 3.14.0
    Relevant elements:
      Found:
        uridecodebin
        souphttpsrc
        appsrc
        alsasink
        osssink
        oss4sink
        pulsesink
        id3demux
        id3v2mux
        lamemp3enc
        mad
        mpegaudioparse
        vorbisdec
        vorbisenc
        vorbisparse
        oggdemux
        oggmux
        oggparse
        flacdec
        flacparse
        shout2send
      Not found:
        flump3dec
        mpg123audiodec

@disconnect5852
Copy link

Same happens here, "GStreamer error: gst-resource-error-quark: Forbidden (15)"
Everything is the newest. With mopidy-spotify there is no such error

@marcik4
Copy link

marcik4 commented Mar 27, 2017

BTW - not a proper solution, but I run now simple watchdog on the logs, and just tell mpd to play next song when this happens. It sucks, but better than a full stop.

tail -F /var/log/mopidy.log | awk '/GStreamer error: gst-resource-error-quark: Forbidden/ {system("mpc next")}'

@kingosticks
Copy link
Member

Spotify uses a very different method of accessing gstreamer so it'd be interesting if any of the other backends showed this issue. Literally any other backend.

@belak
Copy link
Contributor

belak commented Mar 27, 2017

I'd be interested in seeing if there's anything useful in the gmusicapi logs...

That's located at ~/.cache/gmusicapi/log/gmusicapi.log on linux. Please note that this may contain the clientID/deviceID, so you may want to edit those out.

@disconnect5852
Copy link

disconnect5852 commented Mar 27, 2017

No, nothing in that file when error, only the info about opening a new file, the normal things.

@wf1nder
Copy link
Author

wf1nder commented Mar 28, 2017

@sphaugh

Can you try a different gstreamer package and let us know?

Tried different versions of gstreamer before, in different linux distros, and have the same issue.

@shark0der
Copy link

Affects me as well and it's annoying as hell - literally can't listen to Google music anymore because of this, it just stops after a couple of minutes.

Since it's on Google's side, can't we mimic Google Music app and download the songs in a similar fashion?

@belak
Copy link
Contributor

belak commented Mar 30, 2017

I'd love to do that, but then we'd need to manage our own cache directory and handle that sort of thing so we can hand mopidy local URLs... which would be possible since we're given IDs... but it would be a fairly large rewrite of the playback portion.

@belak
Copy link
Contributor

belak commented Mar 30, 2017

Well, if it makes anyone here feel better, I can finally reproduce it. I'll see if I can nail it down and get an update here soon-ish.

belak added a commit to belak-forks/mopidy that referenced this issue Mar 30, 2017
This aims to fix mopidy/mopidy-gmusic#161 by grabbing the whole song at once
rather than buffering.
@belak
Copy link
Contributor

belak commented Mar 30, 2017

There's an experimental fix against mopidy here: mopidy/mopidy#1608

I'm testing this locally, but this should fix the issue 🤞. I've made it through 6 tracks so far and it's worked fine (before it would trigger after 1 or 2).

If anyone here is familiar with running mopidy from git and has been running into this, I'd appreciate more testers.

If you're not comfortable with that, it may help to set the bitrate to 160 rather than 320, but that's a temporary fix.

@belak
Copy link
Contributor

belak commented Mar 30, 2017

There are a number of possibilities here, but the main complications are that gmusic stream URLs expire after 90 seconds and gstreamer will sometimes hit the URL more than once, possibly if the connection is closed (I didn't get that deep into debugging it).

Mopidy attempts to make this less of an issue by providing a fairly large buffer (5M) but also limits it to 5 seconds. I'm not sure how these values interact.

So, what I think is happening:

  • User requests a song to play
  • Gstreamer starts buffering but doesn't download the whole song
  • Gstreamer runs out of buffer so it tries to continue the stream
  • Somehow the connection was already closed perhaps because 5 MB was buffered initially but the file is larger than this and, so Gstreamer tries to make another request.
  • If an mp3 is larger than 5M, there's a large chance it's longer than 90s which would put it past the expiration time for the stream when it goes to refresh it, so when it makes the new request, the stream has already expired. Because of this, I'd expect this to happen more on longer tracks. This is also why reducing the bitrate may help.

Other possibilities are weird interactions between the internal bitrate and what we're guessing... and the possibility that Google changed the default to 320. However, I don't have any insight into what happens at Google, so I can't know for sure what caused this.

I've now made it through a full album without any issues, so I think my hunch may be correct. :)

@shark0der
Copy link

I've installed it using pip install 'git+https://github.com/belak/mopidy@0d87a2a#egg=mopidy' --upgrade (correct me if there's something wrong).

I created a playlist with 6 podcasts (30-60') and I'm listening to them already for a couple of hours - works great! Thanks a lot!

@shark0der
Copy link

shark0der commented Apr 1, 2017

Found a track that still stops, pretty much reproducible every time, it stops around 4:10: gmusic:track:6e673e49-2035-3d06-9bf4-4ab511440ac7 (Dream Stalker by Hybrid, I Choose Noise (Bonus Track)). Total track length: 6:29.

After it stops, if I press the "|<<" (previous) button, it (probably retries the download and then) continues to play from where it stopped.

I can provide os & software versions / logs / other info as requested, can test PRs/commits if necessary.

@belak
Copy link
Contributor

belak commented Apr 3, 2017

Is that an uploaded track, or an All Access track?

@shark0der
Copy link

shark0der commented Apr 3, 2017 via email

@belak
Copy link
Contributor

belak commented Apr 3, 2017

Hm, I can't reproduce it with gmusic:track:Tuicpadq7f2stsgqw34rrkza6dq which seems to correspond to the song you mentioned. All Access track IDs should always start with a T, so I'm not sure where that UUID is even coming from.

@shark0der
Copy link

shark0der commented Apr 3, 2017 via email

@belak
Copy link
Contributor

belak commented Apr 3, 2017

Easiest way is to get it from the "share" link on the official web frontend. That works for albums, artists and tracks.

@belak
Copy link
Contributor

belak commented Apr 3, 2017

This issue does seem to happen much more on the rPI... I guess my fix doesn't fix it everywhere.

@xtedy
Copy link

xtedy commented Apr 4, 2017

pip install 'git+https://github.com/belak/mopidy@0d87a2a#egg=mopidy' --upgrade
works great for me . Thanks

@shark0der
Copy link

Easiest way is to get it from the "share" link on the official web frontend

Can you tell me please which one is the official frontend? I have a couple of them installed but none has a "share" link on a album/artist.

image

@kingosticks
Copy link
Member

I think he's referring to https://play.google.com/music

@kingosticks
Copy link
Member

I've been digging through the gstsouphttp source and I can't see where it has support for bypassing specific domains. I'll investigate more and take it up with the gstreamer folks.

@aschmitz
Copy link

aschmitz commented Dec 5, 2017

I've been running @kingosticks' proxy branch for a few weeks now and it's working wonderfully. I know it doesn't necessarily work well with proxy support, but if there's a way to get that working, I'd suggest using the branch: it appears to have fully fixed this issue.

@kingosticks
Copy link
Member

The proxy support in gstreamer is a total mess, it's implemented differently for each element. The only thing that appears consistent across the elements is that the proxy option mopidy uses will override all other proxy/noproxy environment variables. Unfortunately i don't see how my workaround can be made http proxy compatible so I guess it's no good. Shame.

@brandonfyia
Copy link

I'm having this issue as well. Some music will play through a whole album with no issues, some stop 1-2 mins into the track. same error every time:

root@MusicBox:~# tail /var/log/mopidy/mopidy.log
2019-01-04 19:20:18,852 - WARNING  Element doesn't implement handling of this stream. Please file a bug.
2019-01-04 19:22:39,643 - ERROR    Could not open resource for reading.
2019-01-04 19:23:36,748 - WARNING  Element doesn't implement handling of this stream. Please file a bug.
2019-01-04 19:26:02,032 - ERROR    Could not open resource for reading.
2019-01-04 19:27:03,123 - WARNING  Element doesn't implement handling of this stream. Please file a bug.
2019-01-04 19:28:58,454 - ERROR    Could not open resource for reading.
2019-01-04 19:39:03,092 - WARNING  Element doesn't implement handling of this stream. Please file a bug.
2019-01-04 19:40:41,776 - ERROR    Could not open resource for reading.
2019-01-04 19:44:33,076 - WARNING  Element doesn't implement handling of this stream. Please file a bug.
2019-01-04 19:46:48,951 - ERROR    Could not open resource for reading.

lieuwex pushed a commit to lieuwex/mopidy that referenced this issue Jan 12, 2019
This aims to fix mopidy/mopidy-gmusic#161 by grabbing the whole song at once
rather than buffering.
@morgoth
Copy link

morgoth commented Jan 17, 2019

I can see that mopidy/mopidy#1608 is not merged yet. Is it still the best workaround or is there some other way?
Having this problem quite often...

@lieuwex
Copy link

lieuwex commented Jan 17, 2019

@morgoth I'm running it with the patch locally and it has worked wonders for me

@morgoth
Copy link

morgoth commented Jan 18, 2019

@lieuwex It doesn't work for me - I applied a change by hand in /usr/local/lib/python2.7/dist-packages/mopidy/audio/actor.py and restarted mopidy server.
Is there maybe some cache that I need to clear to make it work?

@brandonfyia
Copy link

@lieuwex can you point me to directions to do this?

@lieuwex
Copy link

lieuwex commented Jan 18, 2019

@morgoth I'm not that experienced with python but I guess it has some cache (.pyc files iirc)

@morgoth @brandonfyia

In your shell ((ba)sh):

cd
git clone https://github.com/lieuwex/mopidy.git
cd mopidy
pip2 install virtualenv
virtualenv --system-site-packages -p python2.7 env
source env/bin/activate
pip2 install --editable .

You can now run ~/mopidy/env/bin/mopidy to start mopidy.

@Yaroslav-95
Copy link

I wasn't having this issue until like a month ago when I reinstalled Arch. Now some tracks will play perfectly without interruption from beginning to end, and some will just randomly stop after 1-2 minutes of playback with the following error:

ERROR    GStreamer error: gst-resource-error-quark: Forbidden (15)

I have installed the following versions from the official repos and from aur:

local/mopidy 2.2.2-1
    An extensible music server written in Python
local/mopidy-gmusic 3.0.0-1
    Mopidy extension for playing music from Google Play Music

@apurohit
Copy link

I can confirm that the fix mopidy/mopidy#1608 worked for me. I also manually applied the change to the actor.py file

I was having the exact same issue Yaroslav-95. I began having this issue only last week. I have been using mopidy-gmusic with Snapcast (snapserver / snapclient) setup.

I am running Ubuntu 18.04.1 LTS with Mopidy 2.2.2 & Mopidy-GMusic 3.0.0 installed as local user. I re-installed mopidy and all extensions prior to making the change.

I checked through network monitor that gmusic did download the entire file just prior to starting playback of a track.

@Yaroslav-95
Copy link

Thank you very much, that seems to have fixed the problem at least for now. For anybody else that is figuring out how to fix this problem by adding the download flag, the actor.py file is located in /lib/python2.7/site-packages/mopidy/audio/actor.py (at least in Arch). Just modify this line:

_GST_PLAY_FLAGS_AUDIO = 0x02

So that it looks like this

_GST_PLAY_FLAGS_AUDIO = 0x02 + 0x80

@karladolfeichmann
Copy link

unfortunately the "download" flag fix (mopidy/mopidy#1608) doesn't seem to work on rPi raspbian installations (mopidy 2.2.2). still getting same error (GStreamer error: gst-resource-error-quark: Forbidden (15))

@jjok
Copy link
Contributor

jjok commented Mar 12, 2020

I've been having play randomly stop recently. I need to check the logs and see if it's the same issue.

@jjok
Copy link
Contributor

jjok commented Mar 12, 2020

@karladolfeichmann That pull request hasn't been merged yet. The fix is only available in a branch.

@ghost
Copy link

ghost commented May 8, 2020

proposal:

i think the issue might be due to a change in the URI signature.

if you focus on the signature and port numbers, you'll see a change in both when this error occurs. it does happen intermittently like it did in this example.

this seems to happen within the time frame that @belak and others mentioned earlier in this thread. once a certain amount of time has elapsed, the URI changes and generates a new signature and sometimes uses a different port number. i think it's important to note that the key always stays the same during the stream.

this tells me that balek's fix is really just a workaround. pulling the full stream down first and then playing it back by cache just skirts around the fact that google sent a new response that seems to interrupt playback.

following the previous logic that balek proposed we can then assume that the frame buffer allots what it can, does not run out of space, and then the request times out... once the request times out, google's server generates a new signature, responds with a new URI containing the new signature, and sends it to the client. the client compares the signature, and because the signature is different from the previous, and it then triggers the error.

a potential fix to the problem would be to update the signature once the timeout has occurred. this would effectively stop the signature comparison from failing.

keep in mind that this is just a rough guess. i have not taken the time to look at mopidy or mopidy-gmusic source code yet. i'll report back if i have any success because i am interested in getting this resolved for my self and i might as well contribute if i come up with a fix.

notes and observations:
as others have noted about making changes to the proxy... i can't say there's really any relevance with that. a proxy is just an AP that behaves like a middle man. after investigating the logs and running debug with repetitive testing while grabbing live output, it always seems to happen when URI signature changes.

lowering the bit rate also seems to help, but barely at all. the reason being that the URI changed after a certain amount of time had elapsed triggering the error anyway regardless of the buffer status.

its also important to note the 403 error that is occurring. this means that the server understands the request but isn't allowing it. hashes are used to compare data securely and if it changes, it will fail when a comparison finally occurs.

The HTTP 403 Forbidden client error status response code indicates that the server understood the request but refuses to authorize it.

source: Mozilla Developer Network

This could be a potential hint to the need to update the signature before the timeout occurs. that way when a request is finally made again (after mopidy has idled for x amount of time), google receives the hash it's expecting to see.

full debug log:

DEBUG    2020-05-08 00:23:10,301 [47642:MpdSession-16] mopidy_mpd.session
  Response to [::ffff:127.0.0.1]:51780: OK
DEBUG    2020-05-08 00:23:10,301 [47642:MpdSession-16] mopidy_mpd.session
  Request from [::ffff:127.0.0.1]:51780: status
DEBUG    2020-05-08 00:23:10,302 [47642:MpdSession-16] mopidy_mpd.session
  Response to [::ffff:127.0.0.1]:51780: 
    volume: 100
    repeat: 0
    random: 0
    single: 0
    consume: 0
    playlist: 14
    playlistlength: 10
    xfade: 0
    state: play
    song: 3
    songid: 6
    nextsong: 4
    nextsongid: 7
    time: 113:302
    elapsed: 113.867
    bitrate: 160
    OK
DEBUG    2020-05-08 00:23:10,303 [47642:MpdSession-16] mopidy_mpd.session
  Request from [::ffff:127.0.0.1]:51780: currentsong
DEBUG    2020-05-08 00:23:10,303 [47642:MpdSession-16] mopidy_mpd.session
  Response to [::ffff:127.0.0.1]:51780: 
    file: gmusic:track:T5n65l7zzmpnr6k5siz325w4ppm
    Time: 302
    Artist: Itro
    Album: Bliss EP
    Title: Dreams
    Date: 2015
    Track: 2
    Pos: 3
    Id: 6
    AlbumArtist: Itro
    Disc: 1
    X-AlbumUri: gmusic:album:B4f4sppqcm2yr2cmpc3ozn7s43i
    OK
DEBUG    2020-05-08 00:23:10,354 [47642:MpdSession-14] mopidy_mpd.session
  Request from [::ffff:127.0.0.1]:51772: noidle
DEBUG    2020-05-08 00:23:10,354 [47642:MpdSession-14] mopidy_mpd.session
  Response to [::ffff:127.0.0.1]:51772: OK
DEBUG    2020-05-08 00:23:10,354 [47642:MpdSession-14] mopidy_mpd.session
  Request from [::ffff:127.0.0.1]:51772: status
DEBUG    2020-05-08 00:23:10,355 [47642:MpdSession-15] mopidy_mpd.session
  Request from [::ffff:127.0.0.1]:51774: noidle
DEBUG    2020-05-08 00:23:10,356 [47642:MpdSession-15] mopidy_mpd.session
  Response to [::ffff:127.0.0.1]:51774: OK
DEBUG    2020-05-08 00:23:10,356 [47642:MpdSession-15] mopidy_mpd.session
  Request from [::ffff:127.0.0.1]:51774: status
DEBUG    2020-05-08 00:23:10,357 [47642:MpdSession-14] mopidy_mpd.session
  Response to [::ffff:127.0.0.1]:51772: 
    volume: 100
    repeat: 0
    random: 0
    single: 0
    consume: 0
    playlist: 14
    playlistlength: 10
    xfade: 0
    state: play
    song: 3
    songid: 6
    nextsong: 4
    nextsongid: 7
    time: 113:302
    elapsed: 113.921
    bitrate: 160
    OK
DEBUG    2020-05-08 00:23:10,358 [47642:MpdSession-15] mopidy_mpd.session
  Response to [::ffff:127.0.0.1]:51774: 
    volume: 100
    repeat: 0
    random: 0
    single: 0
    consume: 0
    playlist: 14
    playlistlength: 10
    xfade: 0
    state: play
    song: 3
    songid: 6
    nextsong: 4
    nextsongid: 7
    time: 113:302
    elapsed: 113.922
    bitrate: 160
    OK
DEBUG    2020-05-08 00:23:10,358 [47642:MpdSession-14] mopidy_mpd.session
  Request from [::ffff:127.0.0.1]:51772: idle
DEBUG    2020-05-08 00:23:10,359 [47642:MpdSession-15] mopidy_mpd.session
  Request from [::ffff:127.0.0.1]:51774: idle
DEBUG    2020-05-08 00:23:10,384 [47642:MpdSession-16] mopidy_mpd.session
  Request from [::ffff:127.0.0.1]:51780: idle
DEBUG    2020-05-08 00:23:10,384 [47642:MpdSession-16] mopidy_mpd.session
  Request from [::ffff:127.0.0.1]:51780: noidle
DEBUG    2020-05-08 00:23:10,384 [47642:MpdSession-16] mopidy_mpd.session
  Response to [::ffff:127.0.0.1]:51780: OK
DEBUG    2020-05-08 00:23:10,465 [47642:MpdSession-16] mopidy_mpd.session
  Request from [::ffff:127.0.0.1]:51780: idle
DEBUG    2020-05-08 00:23:10,507 [47642:MpdSession-16] mopidy_mpd.session
  Request from [::ffff:127.0.0.1]:51780: noidle
DEBUG    2020-05-08 00:23:10,508 [47642:MpdSession-16] mopidy_mpd.session
  Response to [::ffff:127.0.0.1]:51780: OK
DEBUG    2020-05-08 00:23:10,589 [47642:MpdSession-16] mopidy_mpd.session
  Request from [::ffff:127.0.0.1]:51780: idle
DEBUG    2020-05-08 00:23:10,590 [47642:MpdSession-16] mopidy_mpd.session
  Request from [::ffff:127.0.0.1]:51780: noidle
DEBUG    2020-05-08 00:23:10,590 [47642:MpdSession-16] mopidy_mpd.session
  Response to [::ffff:127.0.0.1]:51780: OK
DEBUG    2020-05-08 00:23:10,671 [47642:MpdSession-16] mopidy_mpd.session
  Request from [::ffff:127.0.0.1]:51780: idle
DEBUG    2020-05-08 00:23:10,671 [47642:MpdSession-16] mopidy_mpd.session
  Request from [::ffff:127.0.0.1]:51780: noidle
DEBUG    2020-05-08 00:23:10,672 [47642:MpdSession-16] mopidy_mpd.session
  Response to [::ffff:127.0.0.1]:51780: OK
DEBUG    2020-05-08 00:23:10,753 [47642:MpdSession-16] mopidy_mpd.session
  Request from [::ffff:127.0.0.1]:51780: idle
DEBUG    2020-05-08 00:23:10,795 [47642:MpdSession-16] mopidy_mpd.session
  Request from [::ffff:127.0.0.1]:51780: noidle
DEBUG    2020-05-08 00:23:10,795 [47642:MpdSession-16] mopidy_mpd.session
  Response to [::ffff:127.0.0.1]:51780: OK
DEBUG    2020-05-08 00:23:10,876 [47642:MpdSession-16] mopidy_mpd.session
  Request from [::ffff:127.0.0.1]:51780: idle
DEBUG    2020-05-08 00:23:10,876 [47642:MpdSession-16] mopidy_mpd.session
  Request from [::ffff:127.0.0.1]:51780: noidle
DEBUG    2020-05-08 00:23:10,876 [47642:MpdSession-16] mopidy_mpd.session
  Response to [::ffff:127.0.0.1]:51780: OK
DEBUG    2020-05-08 00:23:10,957 [47642:MpdSession-16] mopidy_mpd.session
  Request from [::ffff:127.0.0.1]:51780: idle
DEBUG    2020-05-08 00:23:10,958 [47642:MpdSession-16] mopidy_mpd.session
  Request from [::ffff:127.0.0.1]:51780: noidle
DEBUG    2020-05-08 00:23:10,959 [47642:MpdSession-16] mopidy_mpd.session
  Response to [::ffff:127.0.0.1]:51780: OK
DEBUG    2020-05-08 00:23:11,040 [47642:MpdSession-16] mopidy_mpd.session
  Request from [::ffff:127.0.0.1]:51780: idle
DEBUG    2020-05-08 00:23:11,083 [47642:MpdSession-16] mopidy_mpd.session
  Request from [::ffff:127.0.0.1]:51780: noidle
DEBUG    2020-05-08 00:23:11,083 [47642:MpdSession-16] mopidy_mpd.session
  Response to [::ffff:127.0.0.1]:51780: OK
DEBUG    2020-05-08 00:23:11,164 [47642:MpdSession-16] mopidy_mpd.session
  Request from [::ffff:127.0.0.1]:51780: idle
DEBUG    2020-05-08 00:23:11,164 [47642:MpdSession-16] mopidy_mpd.session
  Request from [::ffff:127.0.0.1]:51780: noidle
DEBUG    2020-05-08 00:23:11,164 [47642:MpdSession-16] mopidy_mpd.session
  Response to [::ffff:127.0.0.1]:51780: OK
DEBUG    2020-05-08 00:23:11,245 [47642:MpdSession-16] mopidy_mpd.session
  Request from [::ffff:127.0.0.1]:51780: idle
DEBUG    2020-05-08 00:23:11,245 [47642:MpdSession-16] mopidy_mpd.session
  Request from [::ffff:127.0.0.1]:51780: noidle
DEBUG    2020-05-08 00:23:11,246 [47642:MpdSession-16] mopidy_mpd.session
  Response to [::ffff:127.0.0.1]:51780: OK
ERROR    2020-05-08 00:23:11,288 [47642:MainThread] mopidy.audio.gst
  GStreamer error: Forbidden
DEBUG    2020-05-08 00:23:11,288 [47642:MainThread] mopidy.audio.gst
  Got ERROR bus message: error=GLib.Error('Forbidden', 'gst-resource-error-quark', 15) debug='gstsouphttpsrc.c(1433): gst_soup_http_src_parse_status (): /GstPlayBin:playbin0/GstURIDecodeBin:uridecodebin0/GstSoupHTTPSrc:source:\nForbidden (403), URL: https://r2---sn-1gi7znes.c.doc-0-0-sj.sj.googleusercontent.com/videoplayback?id=69dcf793b2f0ee7f&itag=201&source=skyjam&begin=0&ei=NN60XoznII201wLhz6XIAg&o=03122139515636150556&cmbypass=yes&ratebypass=yes&cpn=HX1PmnE-O_GJtZbX0J_hhQ&ip=0.0.0.0&ipbits=0&expire=1588911758&sparams=cmbypass,ei,expire,id,initcwndbps,ip,ipbits,itag,mh,mip,mm,mn,ms,mv,mvi,o,pl,ratebypass,source&signature=2D21FE4557BD538D6C29C68ACF6BE27943A1A6BE.32C4502EC2596D558E65EC713524386C65DDE8A7&key=cms1&initcwndbps=5860&mh=ph&mip=xxx.xxx.xxx.xxx&mm=31&mn=sn-1gi7znes&ms=au&mt=1588911578&mv=m&mvi=1&pl=27, Redirect to: https://r2---sn-4g5ednse.c.doc-0-0-sj.sj.googleusercontent.com/videoplayback?id=69dcf793b2f0ee7f&itag=201&source=skyjam&begin=0&ei=NN60XoznII201wLhz6XIAg&o=03122139515636150556&cmbypass=yes&ratebypass=yes&cpn=HX1PmnE-O_GJtZbX0J_hhQ&ip=0.0.0.0&ipbits=0&expire=1588911758&sparams=cmbypass,ei,expire,id,ip,ipbits,itag,mh,mip,mm,mn,ms,mv,mvi,o,pl,ratebypass,source&signature=795C7780FA01EFD705F7C725663DA135599F633B.4A43B986A502D0D8DD5E1A2AC0D5237626539556&key=cms1&mh=ph&mip=xxx.xxx.xxx.xxx&mvi=1&pl=27&redirect_counter=1&cm2rm=sn-1giez7l&req_id=5808ee077a59a3ee&cms_redirect=yes&mm=34&mn=sn-4g5ednse&ms=ltu&mt=1588911567&mv=m'
DEBUG    2020-05-08 00:23:11,294 [47642:MainThread] mopidy.audio.gst
  Changing state to GST_STATE_NULL: result=GST_STATE_CHANGE_SUCCESS
DEBUG    2020-05-08 00:23:11,326 [47642:MpdSession-16] mopidy_mpd.session
  Request from [::ffff:127.0.0.1]:51780: idle
DEBUG    2020-05-08 00:23:11,359 [47642:MpdSession-14] mopidy_mpd.session
  Request from [::ffff:127.0.0.1]:51772: noidle
DEBUG    2020-05-08 00:23:11,359 [47642:MpdSession-14] mopidy_mpd.session
  Response to [::ffff:127.0.0.1]:51772: OK
DEBUG    2020-05-08 00:23:11,360 [47642:MpdSession-15] mopidy_mpd.session
  Request from [::ffff:127.0.0.1]:51774: noidle
DEBUG    2020-05-08 00:23:11,360 [47642:MpdSession-14] mopidy_mpd.session
  Request from [::ffff:127.0.0.1]:51772: status
DEBUG    2020-05-08 00:23:11,360 [47642:MpdSession-15] mopidy_mpd.session
  Response to [::ffff:127.0.0.1]:51774: OK
DEBUG    2020-05-08 00:23:11,362 [47642:Audio-2] mopidy.audio.actor
  Position query failed
DEBUG    2020-05-08 00:23:11,362 [47642:MpdSession-15] mopidy_mpd.session
  Request from [::ffff:127.0.0.1]:51774: status
DEBUG    2020-05-08 00:23:11,363 [47642:MpdSession-14] mopidy_mpd.session
  Response to [::ffff:127.0.0.1]:51772: 
    volume: 100
    repeat: 0
    random: 0
    single: 0
    consume: 0
    playlist: 14
    playlistlength: 10
    xfade: 0
    state: play
    song: 3
    songid: 6
    nextsong: 4
    nextsongid: 7
    time: 0:302
    elapsed: 0.000
    bitrate: 160
    OK
DEBUG    2020-05-08 00:23:11,365 [47642:MpdSession-14] mopidy_mpd.session
  Request from [::ffff:127.0.0.1]:51772: idle
DEBUG    2020-05-08 00:23:11,365 [47642:Audio-2] mopidy.audio.actor
  Position query failed
DEBUG    2020-05-08 00:23:11,365 [47642:MpdSession-15] mopidy_mpd.session
  Response to [::ffff:127.0.0.1]:51774: 
    volume: 100
    repeat: 0
    random: 0
    single: 0
    consume: 0
    playlist: 14
    playlistlength: 10
    xfade: 0
    state: play
    song: 3
    songid: 6
    nextsong: 4
    nextsongid: 7
    time: 0:302
    elapsed: 0.000
    bitrate: 160
    OK
DEBUG    2020-05-08 00:23:11,366 [47642:MpdSession-15] mopidy_mpd.session
  Request from [::ffff:127.0.0.1]:51774: idle
DEBUG    2020-05-08 00:23:11,371 [47642:MpdSession-16] mopidy_mpd.session
  Request from [::ffff:127.0.0.1]:51780: noidle
DEBUG    2020-05-08 00:23:11,371 [47642:MpdSession-16] mopidy_mpd.session
  Response to [::ffff:127.0.0.1]:51780: OK
DEBUG    2020-05-08 00:23:11,371 [47642:MpdSession-16] mopidy_mpd.session
  Request from [::ffff:127.0.0.1]:51780: status
DEBUG    2020-05-08 00:23:11,373 [47642:Audio-2] mopidy.audio.actor
  Position query failed
DEBUG    2020-05-08 00:23:11,373 [47642:MpdSession-16] mopidy_mpd.session
  Response to [::ffff:127.0.0.1]:51780: 
    volume: 100
    repeat: 0
    random: 0
    single: 0
    consume: 0
    playlist: 14
    playlistlength: 10
    xfade: 0
    state: play
    song: 3
    songid: 6
    nextsong: 4
    nextsongid: 7
    time: 0:302
    elapsed: 0.000
    bitrate: 160
    OK
DEBUG    2020-05-08 00:23:11,373 [47642:MpdSession-16] mopidy_mpd.session
  Request from [::ffff:127.0.0.1]:51780: currentsong
DEBUG    2020-05-08 00:23:11,374 [47642:MpdSession-16] mopidy_mpd.session
  Response to [::ffff:127.0.0.1]:51780: 
    file: gmusic:track:T5n65l7zzmpnr6k5siz325w4ppm
    Time: 302
    Artist: Itro
    Album: Bliss EP
    Title: Dreams
    Date: 2015
    Track: 2
    Pos: 3
    Id: 6
    AlbumArtist: Itro
    Disc: 1
    X-AlbumUri: gmusic:album:B4f4sppqcm2yr2cmpc3ozn7s43i
    OK
DEBUG    2020-05-08 00:23:11,455 [47642:MpdSession-16] mopidy_mpd.session
  Request from [::ffff:127.0.0.1]:51780: idle

debug error:

ERROR    2020-05-08 00:23:11,288 [47642:MainThread] mopidy.audio.gst
  GStreamer error: Forbidden
DEBUG    2020-05-08 00:23:11,288 [47642:MainThread] mopidy.audio.gst
  Got ERROR bus message: error=GLib.Error('Forbidden', 'gst-resource-error-quark', 15) debug='gstsouphttpsrc.c(1433): gst_soup_http_src_parse_status (): /GstPlayBin:playbin0/GstURIDecodeBin:uridecodebin0/GstSoupHTTPSrc:source:\nForbidden (403), URL: https://r2---sn-1gi7znes.c.doc-0-0-sj.sj.googleusercontent.com/videoplayback?id=69dcf793b2f0ee7f&itag=201&source=skyjam&begin=0&ei=NN60XoznII201wLhz6XIAg&o=03122139515636150556&cmbypass=yes&ratebypass=yes&cpn=HX1PmnE-O_GJtZbX0J_hhQ&ip=0.0.0.0&ipbits=0&expire=1588911758&sparams=cmbypass,ei,expire,id,initcwndbps,ip,ipbits,itag,mh,mip,mm,mn,ms,mv,mvi,o,pl,ratebypass,source&signature=2D21FE4557BD538D6C29C68ACF6BE27943A1A6BE.32C4502EC2596D558E65EC713524386C65DDE8A7&key=cms1&initcwndbps=5860&mh=ph&mip=xxx.xxx.xxx.xxx&mm=31&mn=sn-1gi7znes&ms=au&mt=1588911578&mv=m&mvi=1&pl=27, Redirect to: https://r2---sn-4g5ednse.c.doc-0-0-sj.sj.googleusercontent.com/videoplayback?id=69dcf793b2f0ee7f&itag=201&source=skyjam&begin=0&ei=NN60XoznII201wLhz6XIAg&o=03122139515636150556&cmbypass=yes&ratebypass=yes&cpn=HX1PmnE-O_GJtZbX0J_hhQ&ip=0.0.0.0&ipbits=0&expire=1588911758&sparams=cmbypass,ei,expire,id,ip,ipbits,itag,mh,mip,mm,mn,ms,mv,mvi,o,pl,ratebypass,source&signature=795C7780FA01EFD705F7C725663DA135599F633B.4A43B986A502D0D8DD5E1A2AC0D5237626539556&key=cms1&mh=ph&mip=xxx.xxx.xxx.xxx&mvi=1&pl=27&redirect_counter=1&cm2rm=sn-1giez7l&req_id=5808ee077a59a3ee&cms_redirect=yes&mm=34&mn=sn-4g5ednse&ms=ltu&mt=1588911567&mv=m'
DEBUG    2020-05-08 00:23:11,294 [47642:MainThread] mopidy.audio.gst
  Changing state to GST_STATE_NULL: result=GST_STATE_CHANGE_SUCCESS

@jjok
Copy link
Contributor

jjok commented May 8, 2020

I've got this PR open at the moment, which either fixes or works around the issue by enabling the progressive download buffering option in gstreamer. Not sure why it wasn't mentioned here before.

mopidy/mopidy#1888

It's probably a generally nice to have feature that could potentially help with a variety of streaming issues.

@averydark thanks for investigating. If there's a way to fix this specific issue for this backend we should probably do that too.

@kingosticks
Copy link
Member

kingosticks commented May 8, 2020

We've covered all of this and I thought we understood the problem so I'm confused by this post. We've very much established (maybe elsewhere if it's news here) that download buffering is a workaround. But we should finally merge that PR and I'll do that today. Adjusting the bitrate makes a difference because gstreamer can then buffer a different amount. I think you misunderstand what the proxy is doing, which is fair enough if you have not looked at how Gstreamer works. I'll try again:

  1. Gmuisc provides a uri for the track. The uri is valid (requests are answered) for a certain period of time.
  2. Mopidy sets the uri on gstreamer playback object and triggers the track to change
  3. Gstreamer requests data at that uri until its buffering limits are met. Once there is enough data in the buffer, playback starts using it
  4. For short tracks, everything was buffered at the start and playback had everything available to complete. For longer tracks, at some point more data is required so gstreamer opens a new connection at the original uri and gets more data. Problem is, the uri may have now expired and at which point Gmuisc replies 403 unauthorised.
  5. We could then go and ask Gmuisc for a new valid uri for the track and ideally give that to gstreamer to use and it would carry on. Problem is that when setting a new uri, gstreamer won't actually use it until the track changes.

Hopefully you can now see what the proxy hack was doing and why it works. But it's just another workaround.

A better fix here would be develop a variant of gapless playback that let's us use the new uri but somehow suppress the track changing. I'm really not sure if that is possible without looking again at it. There might also be something in gstreamers new streams support that we could leverage. But as a workaround, download buffering is the best choice right now.

@jjok
Copy link
Contributor

jjok commented May 8, 2020

Thanks Nick. If can get that merged I'll open a PR here to set the download flag.

@ghost
Copy link

ghost commented May 8, 2020

@jjok i will be doing more investigating until i find a fix or give up. i'm just surprised this hasn't been fixed yet because it is a 4 year old problem.

@kingosticks

Problem is, the uri may have now expired and at which point Gmuisc replies 403 unauthorised.

this happens when the client request session expires after a time limit has occurred. that's why setting the bit rate doesn't really fix this issue. caching the whole song isn't a solution mainly because it resorts to downloading the song until it has played it. at that point, you might as well hold on to the song.

We could then go and ask Gmuisc for a new valid uri for the track and ideally give that to gstreamer to use and it would carry on.

that is what i was suggesting as a potential fix.

Problem is that when setting a new uri, gstreamer won't actually use it until the track changes.

this is a good starting point.

There might also be something in gstreamers new streams support that we could leverage.

this is something to look further into.

@kingosticks
Copy link
Member

kingosticks commented May 8, 2020

that's why setting the bit rate doesn't really fix this issue.

Changing the bitrate is absolutely not a fix. It's not even a workaround.

caching the whole song isn't a solution mainly because it resorts to downloading the song until it has played it. at that point, you might as well hold on to the song.

I don't know what you mean here but you can read about Gstreamer's different buffering stgrategies here. It is a fix, it will work, but it's not ideal.

that is what i was suggesting as a potential fix.

Great. We are all on the same page. I'm not sure what their sterams support entails. It might not be useful at all. One more option is to ask Gstreamer to provide a mechanism in souphttpsrc to support what we want to do. Problem is even if they did that tomorrow it would take a long time to filter down for us to use.

@ghost
Copy link

ghost commented May 8, 2020

@kingosticks

I don't know what you mean here

google has a 30 day policy that allows you to download the song for offline usage. the token expires after the 30 days have passed and you have to check in with your account to keep the downloaded content active.

i'm not sure how to go about implementing this kind of behaviour, but it's this is a feature rather than a fix. it's also not what i'm interested in focusing on anyways.

you can read about Gstreamer's different buffering stgrategies here. It is a fix, it will work, but it's not ideal.

thanks. i will take a look when i get around to it. i already forked the code base and i need to start with the docs first so i can get acquainted with it.

i'll make a PR if i come up with anything. unfortunately, it could be a few days, or more, before i even touch the code and come up with a decent solution. i can do some testing once i get there, report my findings, and we can go from there.

@kingosticks
Copy link
Member

Ah I see. We are not talking about saving this download data in any form. That's something else entirely and subject to 30 day policies/whatever licensing, as you say.

The data that gstreamer has in its playback buffer won't touch disk and is discarded once the track changes. The term "download buffering" is just the gstreamer name to distinguish it from other buffering strategies.

@jodal
Copy link
Member

jodal commented Dec 6, 2020

Closing because Google Play Music has been shut down, and this project is being discontinued.

@jodal jodal closed this as completed Dec 6, 2020
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
None yet