Mopidy-SomaFM "Connection aborts with BadStatusLine('ICY 200 OK\r\n',)"

[kevinclevenger]

I'm using mopidy with files, internet archive, and somafm. Every time I try to play anything from SomaFM I get the crash below.

I keep getting an error posting the log so I'll inline the relevant section here, happy to post or email the whole log somewhere as needed: DEBUG 2015-10-07 17:37:28,938 [5471:Core-7] mopidy.core.playback Triggering playback state change event DEBUG 2015-10-07 17:37:28,942 [5471:MainThread] mopidy.listener Sending playback_state_changed to CoreListener: {'old_state': u'stopped', 'new_state': u'playing'} DEBUG 2015-10-07 17:37:28,943 [5471:Audio-2] mopidy.audio.gst State change to GST_STATE_READY: result=GST_STATE_CHANGE_SUCCESS DEBUG 2015-10-07 17:37:28,946 [5471:StreamBackend-4] mopidy.stream.actor Unwrapping stream from URI: http://somafm.com/groovesalad.pls DEBUG 2015-10-07 17:37:28,947 [5471:MainThread] mopidy.audio.gst Got state-changed message: old=GST_STATE_NULL new=GST_STATE_READY pending=GST_STATE_VOID_PENDING INFO 2015-10-07 17:37:29,027 [5471:StreamBackend-4] requests.packages.urllib3.connectionpool Starting new HTTP connection (1): somafm.com DEBUG 2015-10-07 17:37:29,111 [5471:StreamBackend-4] requests.packages.urllib3.connectionpool "GET /groovesalad.pls HTTP/1.1" 200 275 DEBUG 2015-10-07 17:37:29,114 [5471:StreamBackend-4] mopidy.stream.actor Parsed playlist (http://somafm.com/groovesalad.pls) and found new URI: http://uwstream1.somafm.com:80 DEBUG 2015-10-07 17:37:29,114 [5471:StreamBackend-4] mopidy.stream.actor Unwrapping stream from URI: http://uwstream1.somafm.com:80 DEBUG 2015-10-07 17:37:34,118 [5471:StreamBackend-4] mopidy.stream.actor GStreamer failed scanning URI (http://uwstream1.somafm.com:80): Timeout after 4999ms INFO 2015-10-07 17:37:34,121 [5471:StreamBackend-4] requests.packages.urllib3.connectionpool Starting new HTTP connection (1): uwstream1.somafm.com DEBUG 2015-10-07 17:37:34,208 [5471:StreamBackend-4] pykka Exception returned from StreamBackend (urn:uuid:f29c36e3-d0db-4ea5-a386-62ecfe9a00b6) to caller: Traceback (most recent call last): File "/usr/local/lib/python2.7/dist-packages/pykka/actor.py", line 201, in _actor_loop response = self._handle_receive(message) File "/usr/local/lib/python2.7/dist-packages/pykka/actor.py", line 295, in _handle_receive return callee(_message['args'], _message['kwargs']) File "/usr/local/lib/python2.7/dist-packages/mopidy/backend.py", line 245, in change_track uri = self.translate_uri(track.uri) File "/usr/local/lib/python2.7/dist-packages/mopidy/stream/actor.py", line 88, in translate_uri requests_session=self._session) File "/usr/local/lib/python2.7/dist-packages/mopidy/stream/actor.py", line 140, in _unwrap_stream requests_session, uri, timeout=download_timeout) File "/usr/local/lib/python2.7/dist-packages/mopidy/internal/http.py", line 26, in download response = session.get(uri, stream=True, timeout=timeout) File "/usr/local/lib/python2.7/dist-packages/requests/sessions.py", line 477, in get return self.request('GET', url, _kwargs) File "/usr/local/lib/python2.7/dist-packages/requests/sessions.py", line 465, in request resp = self.send(prep, _send_kwargs) File "/usr/local/lib/python2.7/dist-packages/requests/sessions.py", line 573, in send r = adapter.send(request, _kwargs) File "/usr/local/lib/python2.7/dist-packages/requests/adapters.py", line 415, in send raise ConnectionError(err, request=request) ConnectionError: ('Connection aborted.', BadStatusLine('ICY 200 OK\r\n',)) DEBUG 2015-10-07 17:37:34,211 [5471:Core-7] pykka Exception returned from Core (urn:uuid:c4d2cc34-6c3b-4860-aca3-bf1c4b9a0695) to caller: Traceback (most recent call last): File "/usr/local/lib/python2.7/dist-packages/pykka/actor.py", line 201, in _actor_loop response = self._handle_receive(message) File "/usr/local/lib/python2.7/dist-packages/pykka/actor.py", line 295, in _handle_receive return callee(_message['args'], _message['kwargs']) File "/usr/local/lib/python2.7/dist-packages/mopidy/core/playback.py", line 305, in play self._play(tl_track=tl_track, tlid=tlid, on_error_step=1) File "/usr/local/lib/python2.7/dist-packages/mopidy/core/playback.py", line 348, in _play backend.playback.change_track(tl_track.track).get() and File "/usr/local/lib/python2.7/dist-packages/pykka/threading.py", line 52, in get compat.reraise(_self._data['exc_info']) File "/usr/local/lib/python2.7/dist-packages/pykka/compat.py", line 12, in reraise exec('raise tp, value, tb') File "/usr/local/lib/python2.7/dist-packages/pykka/actor.py", line 201, in _actor_loop response = self._handle_receive(message) File "/usr/local/lib/python2.7/dist-packages/pykka/actor.py", line 295, in _handle_receive return callee(_message['args'], _message['kwargs']) File "/usr/local/lib/python2.7/dist-packages/mopidy/backend.py", line 245, in change_track uri = self.translate_uri(track.uri) File "/usr/local/lib/python2.7/dist-packages/mopidy/stream/actor.py", line 88, in translate_uri requests_session=self._session) File "/usr/local/lib/python2.7/dist-packages/mopidy/stream/actor.py", line 140, in _unwrap_stream requests_session, uri, timeout=download_timeout) File "/usr/local/lib/python2.7/dist-packages/mopidy/internal/http.py", line 26, in download response = session.get(uri, stream=True, timeout=timeout) File "/usr/local/lib/python2.7/dist-packages/requests/sessions.py", line 477, in get return self.request('GET', url, _kwargs) File "/usr/local/lib/python2.7/dist-packages/requests/sessions.py", line 465, in request resp = self.send(prep, _send_kwargs) File "/usr/local/lib/python2.7/dist-packages/requests/sessions.py", line 573, in send r = adapter.send(request, *kwargs) File "/usr/local/lib/python2.7/dist-packages/requests/adapters.py", line 415, in send raise ConnectionError(err, request=request) ConnectionError: ('Connection aborted.', BadStatusLine('ICY 200 OK\r\n',)) ERROR 2015-10-07 17:37:34,213 [5471:MpdSession-11] pykka Unhandled exception in MpdSession (urn:uuid:268e3a0e-7053-4b04-9268-7c63dcba0db2): Traceback (most recent call last): File "/usr/local/lib/python2.7/dist-packages/pykka/actor.py", line 201, in _actor_loop response = self._handle_receive(message) File "/usr/local/lib/python2.7/dist-packages/pykka/actor.py", line 304, in _handle_receive return self.on_receive(message) File "/usr/local/lib/python2.7/dist-packages/mopidy/internal/network.py", line 370, in on_receive self.on_line_received(line) File "/usr/local/lib/python2.7/dist-packages/mopidy/mpd/session.py", line 34, in on_line_received response = self.dispatcher.handle_request(line) File "/usr/local/lib/python2.7/dist-packages/mopidy/mpd/dispatcher.py", line 47, in handle_request return self._call_next_filter(request, response, filter_chain) File "/usr/local/lib/python2.7/dist-packages/mopidy/mpd/dispatcher.py", line 68, in _call_next_filter return next_filter(request, response, filter_chain) File "/usr/local/lib/python2.7/dist-packages/mopidy/mpd/dispatcher.py", line 76, in _catch_mpd_ack_errors_filter return self._call_next_filter(request, response, filter_chain) File "/usr/local/lib/python2.7/dist-packages/mopidy/mpd/dispatcher.py", line 68, in _call_next_filter return next_filter(request, response, filter_chain) File "/usr/local/lib/python2.7/dist-packages/mopidy/mpd/dispatcher.py", line 86, in _authenticate_filter return self._call_next_filter(request, response, filter_chain) File "/usr/local/lib/python2.7/dist-packages/mopidy/mpd/dispatcher.py", line 68, in _call_next_filter return next_filter(request, response, filter_chain) File "/usr/local/lib/python2.7/dist-packages/mopidy/mpd/dispatcher.py", line 105, in _command_list_filter response = self._call_next_filter(request, response, filter_chain) File "/usr/local/lib/python2.7/dist-packages/mopidy/mpd/dispatcher.py", line 68, in _call_next_filter return next_filter(request, response, filter_chain) File "/usr/local/lib/python2.7/dist-packages/mopidy/mpd/dispatcher.py", line 134, in _idle_filter response = self._call_next_filter(request, response, filter_chain) File "/usr/local/lib/python2.7/dist-packages/mopidy/mpd/dispatcher.py", line 68, in _call_next_filter return next_filter(request, response, filter_chain) File "/usr/local/lib/python2.7/dist-packages/mopidy/mpd/dispatcher.py", line 147, in _add_ok_filter response = self._call_next_filter(request, response, filter_chain) File "/usr/local/lib/python2.7/dist-packages/mopidy/mpd/dispatcher.py", line 68, in _call_next_filter return next_filter(request, response, filter_chain) File "/usr/local/lib/python2.7/dist-packages/mopidy/mpd/dispatcher.py", line 159, in _call_handler_filter response = self._format_response(self._call_handler(request)) File "/usr/local/lib/python2.7/dist-packages/mopidy/mpd/dispatcher.py", line 174, in _call_handler return protocol.commands.call(tokens, context=self.context) File "/usr/local/lib/python2.7/dist-packages/mopidy/mpd/protocol/init.py", line 180, in call return self.handlers[tokens[0]](context, tokens[1:]) File "/usr/local/lib/python2.7/dist-packages/mopidy/mpd/protocol/init.py", line 158, in validate return func(_callargs) File "/usr/local/lib/python2.7/dist-packages/mopidy/mpd/protocol/playback.py", line 227, in playid return context.core.playback.play(tl_tracks[0]).get() File "/usr/local/lib/python2.7/dist-packages/pykka/threading.py", line 52, in get compat.reraise(_self._data['exc_info']) File "/usr/local/lib/python2.7/dist-packages/pykka/compat.py", line 12, in reraise exec('raise tp, value, tb') File "/usr/local/lib/python2.7/dist-packages/pykka/actor.py", line 201, in _actor_loop response = self._handle_receive(message) File "/usr/local/lib/python2.7/dist-packages/pykka/actor.py", line 295, in _handle_receive return callee(_message['args'], _message['kwargs']) File "/usr/local/lib/python2.7/dist-packages/mopidy/core/playback.py", line 305, in play self._play(tl_track=tl_track, tlid=tlid, on_error_step=1) File "/usr/local/lib/python2.7/dist-packages/mopidy/core/playback.py", line 348, in _play backend.playback.change_track(tl_track.track).get() and File "/usr/local/lib/python2.7/dist-packages/pykka/threading.py", line 52, in get compat.reraise(_self._data['exc_info']) File "/usr/local/lib/python2.7/dist-packages/pykka/compat.py", line 12, in reraise exec('raise tp, value, tb') File "/usr/local/lib/python2.7/dist-packages/pykka/actor.py", line 201, in _actor_loop response = self._handle_receive(message) File "/usr/local/lib/python2.7/dist-packages/pykka/actor.py", line 295, in _handle_receive return callee(_message['args'], _message['kwargs']) File "/usr/local/lib/python2.7/dist-packages/mopidy/backend.py", line 245, in change_track uri = self.translate_uri(track.uri) File "/usr/local/lib/python2.7/dist-packages/mopidy/stream/actor.py", line 88, in translate_uri requests_session=self._session) File "/usr/local/lib/python2.7/dist-packages/mopidy/stream/actor.py", line 140, in _unwrap_stream requests_session, uri, timeout=download_timeout) File "/usr/local/lib/python2.7/dist-packages/mopidy/internal/http.py", line 26, in download response = session.get(uri, stream=True, timeout=timeout) File "/usr/local/lib/python2.7/dist-packages/requests/sessions.py", line 477, in get return self.request('GET', url, _kwargs) File "/usr/local/lib/python2.7/dist-packages/requests/sessions.py", line 465, in request resp = self.send(prep, _send_kwargs) File "/usr/local/lib/python2.7/dist-packages/requests/sessions.py", line 573, in send r = adapter.send(request, _kwargs) File "/usr/local/lib/python2.7/dist-packages/requests/adapters.py", line 415, in send raise ConnectionError(err, request=request) ConnectionError: ('Connection aborted.', BadStatusLine('ICY 200 OK\r\n',)) DEBUG 2015-10-07 17:37:34,216 [5471:MpdSession-11] pykka Unregistered MpdSession (urn:uuid:268e3a0e-7053-4b04-9268-7c63dcba0db2) Traceback (most recent call last): File "/usr/local/lib/python2.7/dist-packages/mopidy/internal/network.py", line 275, in recv_callback self.actor_ref.tell({'close': True}) File "/usr/local/lib/python2.7/dist-packages/pykka/actor.py", line 398, in tell raise ActorDeadError('%s not found' % self) pykka.exceptions.ActorDeadError: MpdSession (urn:uuid:268e3a0e-7053-4b04-9268-7c63dcba0db2) not found DEBUG 2015-10-07 17:37:43,955 [5471:MainThread] pykka Registered MpdSession (urn:uuid:56af07fb-0876-49b1-bebf-ca1573db64c4) DEBUG 2015-10-07 17:37:43,955 [5471:MainThread] pykka Starting MpdSession (urn:uuid:56af07fb-0876-49b1-bebf-ca1573db64c4) INFO 2015-10-07 17:37:43,956 [5471:MpdSession-12] mopidy.mpd.session New MPD connection from [127.0.0.1]:41707 DEBUG 2015-10-07 17:37:43,957 [5471:MpdSession-12] mopidy.mpd.session Request from [127.0.0.1]:41707: status DEBUG 2015-10-07 17:37:43,964 [5471:Audio-2] mopidy.audio.actor Position query failed

$ pip list --local apt-clone (0.2.1) apt-xapian-index (0.47) apturl (0.4.1ubuntu4) audioread (1.0.3) backports.ssl-match-hostname (3.4.0.2) BeautifulSoup (3.2.1) cachetools (1.1.3) certifi (2015.9.6.2) cffi (0.8.6) characteristic (0.1.0) chardet (2.3.0) configglue (1.0) configobj (5.0.6) cryptography (0.6.1) debtagshw (0.1) defer (1.0.6) dirspec (4.2.0) dnspython (1.12.0) duplicity (0.6.24) ecdsa (0.11) feedparser (5.1.3) httplib2 (0.9) ipaddr (2.1.11) ipaddress (1.0.14) lockfile (0.8) lxml (3.4.0) Mako (1.0.0) MarkupSafe (0.23) mercurial (3.1.2) Mopidy (1.1.1) Mopidy-InternetArchive (1.3.0) Mopidy-SomaFM (0.7.1) mutagen (1.25.1) nemo-emblems (0.0.1) numpy (1.8.2) oauthlib (0.6.3) PAM (0.4.2) paramiko (1.15.1) pexpect (3.2) Pillow (2.6.1) pip (7.1.2) ply (3.4) protobuf (2.6.1) pyasn1 (0.1.7) pyasn1-modules (0.0.5) pycparser (2.10) pycrypto (2.6.1) pycups (1.9.63) pycurl (7.19.5) pygobject (3.14.0) pyinotify (0.9.4) PyJWT (0.2.1) Pykka (1.2.1) pyOpenSSL (0.14) pyparted (3.10.0) pyserial (2.6) pysmbc (1.0.15.3) python-apt (0.9.3.12) python-dateutil (2.4.2) python-debian (0.1.27) pyxdg (0.25) reportlab (3.1.8) requests (2.7.0) service-identity (1.0.0) setuptools (18.3.2) simplejson (3.8.0) six (1.8.0) tornado (4.2.1) Twisted-Core (14.0.2) Twisted-Names (14.0.2) Twisted-Web (14.0.2) uritemplate (0.6) uritools (1.0.1) urlgrabber (3.9.1) urllib3 (1.9.1) uTidylib (0.2) wheel (0.25.0) zope.interface (4.1.1)

[adamcik]

This looks like a Mopidy bug, not a somafm one to be honest. Related to changes made for https://github.com/mopidy/mopidy/issues/1250

[adamcik]

https://github.com/kennethreitz/requests/issues/2322 might also be relevant (make that https://github.com/kennethreitz/requests/issues/1869).

[adamcik]

Though the real problem seems to be:

DEBUG 2015-10-07 17:37:29,114 [5471:StreamBackend-4] mopidy.stream.actor
Unwrapping stream from URI: http://uwstream1.somafm.com:80
DEBUG 2015-10-07 17:37:34,118 [5471:StreamBackend-4] mopidy.stream.actor
GStreamer failed scanning URI (http://uwstream1.somafm.com:80): Timeout after 4999ms

That is that we failed the GStreamer scan with a timeout and then fall back to doing a unwrap.

[AlexandrePTJ]

As @adamcik said, this is more Mopidy bug. Did you tried with another channel ?