New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

javascript objects dissappear #571

Closed
woutervanwijk opened this Issue Nov 11, 2013 · 43 comments

Comments

4 participants
@woutervanwijk
Contributor

woutervanwijk commented Nov 11, 2013

When using the webclient with 0.16 (adapted for changes from the changelog), I get an error stating that the mopidy.playback and mopidy.tracklist objects are not defined.
This happens not instantly, but after using the webclient for a while. After that, the Mopidy object is created, but there is no playback or tracklist object.
The same behaviour in multiple browsers and on multiple systems.
After restarting mopidy, the objects are back again,
this is the object in the browser: http://pastebin.com/DW9t0mcD

@ghost ghost assigned jodal Nov 11, 2013

@jodal

This comment has been minimized.

Member

jodal commented Nov 11, 2013

Do you have a branch of Mopidy-Webclient with your 0.16 updates somewhere, so I can try to reproduce it the same way you get this error?

@woutervanwijk

This comment has been minimized.

Contributor

woutervanwijk commented Nov 12, 2013

Yes, just created it. There are two interfaces at the moment, the old one
and a flat one:
https://github.com/woutervanwijk/Mopidy-Webclient/tree/0.16

2013/11/12 Stein Magnus Jodal notifications@github.com

Do you have a branch of Mopidy-Webclient with your 0.16 updates somewhere,
so I can try to reproduce it the same way you get this error?


Reply to this email directly or view it on GitHubhttps://github.com//issues/571#issuecomment-28252461
.


Met Zoek+ vind je meer
www.zoekplus.nl

@jodal

This comment has been minimized.

Member

jodal commented Nov 12, 2013

Ok, I got the 0.16 branch running here now. Seems to work nicely so far.

@woutervanwijk

This comment has been minimized.

Contributor

woutervanwijk commented Nov 12, 2013

Strange. Could be something in my configuration on the Pi then. But what...?

I'll have to switch off the backends one by one I think. This is the log,
with an error:

INFO     Starting Mopidy 0.16.1
INFO     Loading config from: builtin defaults,
/home/musicbox/.config/mopidy/mopidy.conf, command line options
INFO     Enabled extensions: spotify, mpd, http, stream, gmusic, scrobbler,
local, soundcloud
INFO     Disabled extensions: none
INFO     Starting Mopidy audio
INFO     Starting Mopidy backends: LocalBackend, StreamBackend,
SoundCloudBackend, SpotifyBackend, GMusicBackend
INFO     Audio output set to "alsasink"
INFO     Loaded 0 local tracks from /music using
/home/musicbox/.cache/mopidy/tag_cache
INFO     Audio mixer set to "alsamixer" using track "PCM"
INFO     Loaded 0 local playlists from
/home/musicbox/.local/share/mopidy/local/playlists
INFO     Starting new HTTPS connection (1): api.soundcloud.com
INFO     Loaded 5 SoundCloud playlist(s)
INFO     Mopidy uses SPOTIFY(R) CORE
INFO     Mopidy uses Google Music
INFO     !-- begin debug log --!
INFO     version: 2.0.0-dev
INFO     logging to: /home/musicbox/.cache/gmusicapi/log/gmusicapi.log
INFO     initialized
INFO     logged out
INFO     Starting Mopidy core
INFO     Connected to Spotify
INFO     Starting new HTTPS connection (1): www.google.com
INFO     Starting new HTTPS connection (1): play.google.com
INFO     authenticated
INFO     Starting new HTTPS connection (1): www.googleapis.com
INFO     Loaded 139 Spotify playlists
INFO     Starting Mopidy frontends: ScrobblerFrontend, HttpFrontend,
MpdFrontend
INFO     Using epoll
INFO     MPD server running at [::ffff:0.0.0.0]:6600
INFO     Scrobbler connected to Last.fm
INFO     HTTP server running at http://MusicBox:6680
INFO     Managing websocket [Local => 192.168.1.6:6680 | Remote =>
192.168.1.10:50412]
INFO     Terminating websocket [Local => 192.168.1.6:6680 | Remote =>
192.168.1.10:50412]
INFO     Managing websocket [Local => 192.168.1.6:6680 | Remote =>
192.168.1.10:50422]
INFO     Resetting dropped connection: api.soundcloud.com
INFO     Managing websocket [Local => 192.168.1.6:6680 | Remote =>
192.168.1.10:50431]
Exception in thread Thread-11:
Traceback (most recent call last):
  File "/usr/lib/python2.7/threading.py", line 552, in __bootstrap_inner
    self.run()
  File "/usr/lib/python2.7/dist-packages/ws4py/manager.py", line 259, in run
    if not ws.once():
  File "/usr/lib/python2.7/dist-packages/ws4py/websocket.py", line 305, in
once
    if not self.process(b):
  File "/usr/lib/python2.7/dist-packages/ws4py/websocket.py", line 377, in
process
    self.received_message(s.message)
  File "/usr/share/mopidy/mopidy/frontends/http/ws.py", line 68, in
received_message
    self.send(response)
  File "/usr/lib/python2.7/dist-packages/ws4py/websocket.py", line 261, in
send
    self._write(m)
  File "/usr/lib/python2.7/dist-packages/ws4py/websocket.py", line 243, in
_write
    self.sock.sendall(b)
  File "/usr/lib/python2.7/socket.py", line 224, in meth
    return getattr(self._sock,name)(*args)
error: [Errno 32] Broken pipe

INFO     Managing websocket [Local => 192.168.1.6:6680 | Remote =>
192.168.1.10:50438]
INFO     Managing websocket [Local => 192.168.1.6:6680 | Remote =>
192.168.1.10:50439]
INFO     Managing websocket [Local => 192.168.1.6:6680 | Remote =>
192.168.1.10:50447]
INFO     Managing websocket [Local => 192.168.1.6:6680 | Remote =>
192.168.1.10:50479]
INFO     Managing websocket [Local => 192.168.1.6:6680 | Remote =>
192.168.1.10:50661]
@woutervanwijk

This comment has been minimized.

Contributor

woutervanwijk commented Nov 12, 2013

I think it's the google music plugin. Let you know how it works out.

@jodal

This comment has been minimized.

Member

jodal commented Nov 12, 2013

Can you reproduce the error with --save-debug-log? I'm interested in the timestamps, and what messages are sent before the crash.

@jodal

This comment has been minimized.

Member

jodal commented Nov 14, 2013

Does it still look like the GMusic extension causes this?

@woutervanwijk

This comment has been minimized.

Contributor

woutervanwijk commented Nov 19, 2013

I don't know yet. I updated everything using PIP, but it still goes wrong. I'll try the --save-debug-log

INFO     Terminating websocket [Local => 192.168.1.13:6680 | Remote => 192.168.1.14:52732]
INFO     Managing websocket [Local => 192.168.1.13:6680 | Remote => 192.168.1.14:52801]
INFO     Resetting dropped connection: api.soundcloud.com
INFO     Managing websocket [Local => 192.168.1.13:6680 | Remote => 192.168.1.14:52974]
Exception in thread Thread-10:
Traceback (most recent call last):
  File "/usr/lib/python2.7/threading.py", line 552, in __bootstrap_inner
    self.run()
  File "/usr/lib/python2.7/dist-packages/ws4py/manager.py", line 259, in run
    if not ws.once():
  File "/usr/lib/python2.7/dist-packages/ws4py/websocket.py", line 305, in once
    if not self.process(b):
  File "/usr/lib/python2.7/dist-packages/ws4py/websocket.py", line 377, in process
    self.received_message(s.message)
  File "/usr/local/lib/python2.7/dist-packages/mopidy/frontends/http/ws.py", line 68, in received_message
    self.send(response)
  File "/usr/lib/python2.7/dist-packages/ws4py/websocket.py", line 261, in send
    self._write(m)
  File "/usr/lib/python2.7/dist-packages/ws4py/websocket.py", line 243, in _write
    self.sock.sendall(b)
  File "/usr/lib/python2.7/socket.py", line 224, in meth
    return getattr(self._sock,name)(*args)
error: [Errno 32] Broken pipe

INFO     Resetting dropped connection: android.clients.google.com
@jodal

This comment has been minimized.

Member

jodal commented Nov 19, 2013

What ws4py version do you have?

$ python -c 'import ws4py; print ws4py.__version__'
0.3.2
@woutervanwijk

This comment has been minimized.

Contributor

woutervanwijk commented Nov 19, 2013

Ok. managed to create a debug-log. Since it's 3MB, I won't paste it here ;-)
https://www.dropbox.com/s/60oyjlms41pwbu4/mopidy.log.zip

@woutervanwijk

This comment has been minimized.

Contributor

woutervanwijk commented Nov 19, 2013

0.3.2 too

@woutervanwijk

This comment has been minimized.

Contributor

woutervanwijk commented Nov 19, 2013

As for the log: it exactly did as I described above. No tracklist and playlist objects.
To create the error I just randomly clicked on some playlists from GMusic, Spotify and Soundcloud. This would send some random requests for the contents of the different playlists from the different backends to mopidy. Somewhere, it goes wrong...

@woutervanwijk

This comment has been minimized.

Contributor

woutervanwijk commented Nov 19, 2013

mopidy --show-deps:

Platform: Linux-3.6.11+-armv6l-with-debian-7.2
Python: CPython 2.7.3 from /usr/lib/python2.7
Mopidy: 0.16.1 from /usr/local/lib/python2.7/dist-packages
  setuptools: 1.4 from /usr/local/lib/python2.7/dist-packages
  Pykka>=1.1: 1.2.0 from /usr/lib/python2.7/dist-packages
  cherrypy>=3.2.2: 3.2.4 from /usr/local/lib/python2.7/dist-packages
  ws4py>=0.2.3: 0.3.2 from /usr/lib/python2.7/dist-packages
Mopidy-GMusic: 0.2.2 from /usr/local/lib/python2.7/dist-packages
  setuptools: 1.4 from /usr/local/lib/python2.7/dist-packages
  Mopidy>=0.14: 0.16.1 from /usr/local/lib/python2.7/dist-packages
    setuptools: 1.4 from /usr/local/lib/python2.7/dist-packages
    Pykka>=1.1: 1.2.0 from /usr/lib/python2.7/dist-packages
  Pykka>=1.1: 1.2.0 from /usr/lib/python2.7/dist-packages
  gmusicapi>=3.0.0: 3.0.0 from /usr/local/lib/python2.7/dist-packages
    validictory==0.9.1: 0.9.1 from /usr/local/lib/python2.7/dist-packages
    decorator==3.4.0: 3.4.0 from /usr/local/lib/python2.7/dist-packages
    mutagen==1.22: 1.22 from /usr/local/lib/python2.7/dist-packages
    protobuf==2.5.0: 2.5.0 from /usr/local/lib/python2.7/dist-packages
      setuptools: 1.4 from /usr/local/lib/python2.7/dist-packages
    requests==2.0.1: 2.0.1 from /usr/local/lib/python2.7/dist-packages
    python-dateutil==2.1: 2.1 from /usr/local/lib/python2.7/dist-packages
      six: 1.4.1 from /usr/local/lib/python2.7/dist-packages
    proboscis==1.2.5.3: 1.2.5.3 from /usr/local/lib/python2.7/dist-packages
    oauth2client==1.2: 1.2 from /usr/local/lib/python2.7/dist-packages
      httplib2>=0.8: 0.8 from /usr/local/lib/python2.7/dist-packages
    mock==1.0.1: 1.0.1 from /usr/local/lib/python2.7/dist-packages
    appdirs==1.2.0: 1.2.0 from /usr/local/lib/python2.7/dist-packages
Mopidy-Scrobbler: 1.0.0 from /usr/local/lib/python2.7/dist-packages
  setuptools: 1.4 from /usr/local/lib/python2.7/dist-packages
  Mopidy>=0.16a0: 0.16.1 from /usr/local/lib/python2.7/dist-packages
    setuptools: 1.4 from /usr/local/lib/python2.7/dist-packages
    Pykka>=1.1: 1.2.0 from /usr/lib/python2.7/dist-packages
  Pykka>=1.1: 1.2.0 from /usr/lib/python2.7/dist-packages
  pylast>=0.5.7: 0.5.11 from /usr/lib/python2.7/dist-packages
Mopidy-SoundCloud: 1.0.16 from /usr/local/lib/python2.7/dist-packages
  setuptools: 1.4 from /usr/local/lib/python2.7/dist-packages
  Mopidy>=0.14: 0.16.1 from /usr/local/lib/python2.7/dist-packages
    setuptools: 1.4 from /usr/local/lib/python2.7/dist-packages
    Pykka>=1.1: 1.2.0 from /usr/lib/python2.7/dist-packages
  Pykka>=1.1: 1.2.0 from /usr/lib/python2.7/dist-packages
  requests: 2.0.1 from /usr/local/lib/python2.7/dist-packages
Mopidy-Spotify: 1.0.1 from /usr/local/lib/python2.7/dist-packages
  setuptools: 1.4 from /usr/local/lib/python2.7/dist-packages
  Mopidy>=0.16: 0.16.1 from /usr/local/lib/python2.7/dist-packages
    setuptools: 1.4 from /usr/local/lib/python2.7/dist-packages
    Pykka>=1.1: 1.2.0 from /usr/lib/python2.7/dist-packages
  Pykka>=1.1: 1.2.0 from /usr/lib/python2.7/dist-packages
  pyspotify>=1.9,<2: 1.11 from /usr/lib/pymodules/python2.7
GStreamer: 0.10.36.0 from /usr/lib/python2.7/dist-packages/gst-0.10/gst
  Detailed information: 
    Python wrapper: gst-python 0.10.22.0
    Relevant elements:
      Found:
        uridecodebin
        souphttpsrc
        appsrc
        alsamixer
        alsasink
        ossmixer
        osssink
        oss4mixer
        oss4sink
        id3demux
        id3v2mux
        vorbisdec
        vorbisenc
        vorbisparse
        oggdemux
        oggmux
        oggparse
        flacdec
        flacparse
        shout2send
      Not found:
        pulsemixer
        pulsesink
        mp3parse
        mad
        lame
@adamcik

This comment has been minimized.

Member

adamcik commented Nov 19, 2013

Perhaps we can pinpoint when this breaks better by using something like:

function debug() {
  if (mopidy.tracklist === undefined)
    alert('Broke at ' +  new Date())
  else
    setTimeout(debug, 100);
}
debug()

That combined with a debug log might make this easier to pin point.

@woutervanwijk

This comment has been minimized.

Contributor

woutervanwijk commented Nov 20, 2013

I tried that, but it doesn't work for now. It comes up immediately and it seems to make the interface die earlier. But that is just a guess
This is another log (of multiple sessions)
https://www.dropbox.com/s/6rboz9n9vh042wy/mopidy.log-2.zip

@jodal

This comment has been minimized.

Member

jodal commented Nov 20, 2013

I guess it comes up immediately because the mopidy object starts out without any attributes. Try not running the debug() function before the mopidy object is ready for use:

function debug() {
  if (mopidy.tracklist === undefined) {
    alert('Broke at ' +  new Date());
  } else {
    setTimeout(debug, 100);
  }
}
mopidy.on("state:online", debug);
@woutervanwijk

This comment has been minimized.

Contributor

woutervanwijk commented Nov 22, 2013

I'm pretty sure it's the SoundCloud plugin. If I randomly select playlists
from Spotify or GGL, it just works and keeps on working. If I use
Soundcloud, the bug appears. These are the settings I use to test:

[soundcloud]
enabled = true
auth_token = XXX
explore = electronic/Ambient, pop/New Wave, rock/Indie

2013/11/20 Stein Magnus Jodal notifications@github.com

I guess it comes up immediately because the mopidy object starts out
without any attributes. Try not running the debug function before the
mopidy object is ready for use:

function debug() {
if (mopidy.tracklist === undefined) {
alert('Broke at ' + new Date());
} else {
setTimeout(debug, 100);
}}
mopidy.on("state:online", debug);


Reply to this email directly or view it on GitHubhttps://github.com//issues/571#issuecomment-28938953
.


Met Zoek+ vind je meer
www.zoekplus.nl

@woutervanwijk

This comment has been minimized.

Contributor

woutervanwijk commented Nov 22, 2013

I put a test version of mb 0.4 beta over here. It's not final, since
soundcloud doesn't work.
http://woutervanwijk.nl/pimusicbox/musicbox0.4-beta-test.zip

2013/11/22 Wouter van Wijk woutervanwijk@gmail.com

I'm pretty sure it's the SoundCloud plugin. If I randomly select playlists
from Spotify or GGL, it just works and keeps on working. If I use
Soundcloud, the bug appears. These are the settings I use to test:

[soundcloud]
enabled = true
auth_token = XXX
explore = electronic/Ambient, pop/New Wave, rock/Indie

2013/11/20 Stein Magnus Jodal notifications@github.com

I guess it comes up immediately because the mopidy object starts out
without any attributes. Try not running the debug function before the
mopidy object is ready for use:

function debug() {
if (mopidy.tracklist === undefined) {
alert('Broke at ' + new Date());
} else {
setTimeout(debug, 100);
}}
mopidy.on("state:online", debug);


Reply to this email directly or view it on GitHubhttps://github.com//issues/571#issuecomment-28938953
.


Met Zoek+ vind je meer
www.zoekplus.nl


Met Zoek+ vind je meer
www.zoekplus.nl

@jodal

This comment has been minimized.

Member

jodal commented Jan 18, 2014

Hi Wouter, have you had any progress on this?

@woutervanwijk

This comment has been minimized.

Contributor

woutervanwijk commented Jan 23, 2014

In a test of 0.18, it seems to have disappeared :-) I will report it if I
don't encounter it anymore...

2014/1/18 Stein Magnus Jodal notifications@github.com

Hi Wouter, have you had any progress on this?


Reply to this email directly or view it on GitHubhttps://github.com//issues/571#issuecomment-32695220
.


Met Zoek+ vind je meer
www.zoekplus.nl

@adamcik adamcik closed this Jan 24, 2014

@woutervanwijk

This comment has been minimized.

Contributor

woutervanwijk commented Jan 27, 2014

It's still here I'm afraid :-(
It always seems to be an error in the ws4py. It can be different errors I think. Strangely enough, the webinterface keeps receiving correct messages from Mopidy. It just cannot send them anymore. MPD clients keep working fine.

This is an experimental image of musicbox which includes browsing support, and the javascript bug: http://www.pimusicbox.com/musicbox0.5alphaalpha.zip

This is an error I got (I think originiating from a playlist of mopidy-subsonic)

Exception in thread Thread-13:
Traceback (most recent call last):
  File "/usr/lib/python2.7/threading.py", line 552, in __bootstrap_inner
    self.run()
  File "/usr/lib/python2.7/dist-packages/ws4py/manager.py", line 259, in run
    if not ws.once():
  File "/usr/lib/python2.7/dist-packages/ws4py/websocket.py", line 305, in once
    if not self.process(b):
  File "/usr/lib/python2.7/dist-packages/ws4py/websocket.py", line 377, in process
    self.received_message(s.message)
  File "/usr/local/lib/python2.7/dist-packages/mopidy/http/ws.py", line 68, in received_message
    response = self.jsonrpc.handle_json(request)
  File "/usr/local/lib/python2.7/dist-packages/mopidy/utils/jsonrpc.py", line 83, in handle_json
    return json.dumps(response, cls=self.encoder)
  File "/usr/lib/python2.7/json/__init__.py", line 238, in dumps
    **kw).encode(obj)
  File "/usr/lib/python2.7/json/encoder.py", line 200, in encode
    chunks = self.iterencode(o, _one_shot=True)
  File "/usr/lib/python2.7/json/encoder.py", line 263, in iterencode
    return _iterencode(o, 0)
  File "/usr/local/lib/python2.7/dist-packages/mopidy/utils/jsonrpc.py", line 285, in default
    return json.JSONEncoder.default(self, obj)
  File "/usr/lib/python2.7/json/encoder.py", line 177, in default
    raise TypeError(repr(o) + " is not JSON serializable")
TypeError: datetime.datetime(2014, 1, 27, 10, 11, 48) is not JSON serializable
@jodal

This comment has been minimized.

Member

jodal commented Jan 28, 2014

:-/

@jodal jodal reopened this Jan 28, 2014

@jodal

This comment has been minimized.

Member

jodal commented Jan 28, 2014

The exception is caused by Mopidy-Subsonic being the first to use a datetime.datetime object in the Playlist.last_modified field, which is exactly as we've documented our models. Though, our model serializer does not handle this. After some thought, we've now redefined the last_modified field to be milliseconds since Unix epoch as an integer, making serialization simple and the exact meaning of the value well defined. I've opened rattboi/mopidy-subsonic#3 to make sure Mopidy-Subsonic is updated accordingly.

@jodal

This comment has been minimized.

Member

jodal commented Jan 28, 2014

@woutervanwijk Can you reproduce the issue when you don't have Mopidy-Subsonic (or anything else causing errors) installed/enabled?

@jodal

This comment has been minimized.

Member

jodal commented Jan 28, 2014

@woutervanwijk Mopidy-Subsonic 0.3.1 was just released. It removes the use of the last_modified field, and should thus work.

@woutervanwijk

This comment has been minimized.

Contributor

woutervanwijk commented Jan 29, 2014

Yes, sorry to report that I can reproduce it with only the Spotify extension enabled in the image I linked to above. When I browse tracks and choose e.g. the Popular tracks on Spotify, the bug appears again. Sometimes immediately, sometimes after a while. Drives me crazy...!

@woutervanwijk

This comment has been minimized.

Contributor

woutervanwijk commented Jan 30, 2014

I cannot reproduce it on Mopidy running on Ubuntu on my computer.
This is the error log for the Pi:

INFO     Starting Mopidy 0.18.1
INFO     Loading config from: builtin defaults, /etc/xdg/mopidy/mopidy.conf, /home/musicbox/.config/mopidy/mopidy.conf, command line options
INFO     Enabled extensions: local, mpd, http, stream
INFO     Disabled extensions: spotify, gmusic, scrobbler, subsonic, dirble, soundcloud
INFO     Starting Mopidy audio
INFO     Starting Mopidy backends: LocalBackend, StreamBackend
INFO     Loaded 0 local playlists from /home/musicbox/.local/share/mopidy/local/playlists
INFO     Loaded 20 local tracks using json
INFO     Audio output set to "alsasink"
INFO     Audio mixer is using software mixing
INFO     Starting Mopidy core
INFO     Starting Mopidy frontends: HttpFrontend, MpdFrontend
INFO     MPD server running at [::ffff:0.0.0.0]:6600
INFO     Registering MPD with Zeroconf failed.
INFO     HTTP server running at http://MusicBox:6680
INFO     Registering HTTP with Zeroconf failed.
ERROR    Failed to receive data
Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/ws4py/websocket.py", line 300, in once
    b = self.sock.recv(self.reading_buffer_size)
error: [Errno 104] Connection reset by peer
ERROR    Failed to receive data
Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/ws4py/websocket.py", line 300, in once
    b = self.sock.recv(self.reading_buffer_size)
error: [Errno 104] Connection reset by peer
ERROR    Failed to receive data
Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/ws4py/websocket.py", line 300, in once
    b = self.sock.recv(self.reading_buffer_size)
error: [Errno 104] Connection reset by peer
ERROR    Failed to receive data
Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/ws4py/websocket.py", line 300, in once
    b = self.sock.recv(self.reading_buffer_size)
error: [Errno 104] Connection reset by peer
ERROR    Failed to receive data
Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/ws4py/websocket.py", line 300, in once
    b = self.sock.recv(self.reading_buffer_size)
error: [Errno 104] Connection reset by peer
@jodal

This comment has been minimized.

Member

jodal commented Jan 30, 2014

I took at look at the method in question in the ws4py source: https://github.com/Lawouach/WebSocket-for-Python/blob/master/ws4py/websocket.py#L280-L308

It seems that ws4py will log an "exception", which means an error level message with a stack trace, if there is a socket error of any sort, but it will also return a proper value and continue on, so this doesn't look like a very exceptional thing at all, just maybe a bad choice of the amount to log.

@woutervanwijk

This comment has been minimized.

Contributor

woutervanwijk commented Feb 1, 2014

I did a full reinstall of MusicBox on a clean Raspbian and it still appears. I totally don't have an idea how this can occur every time. This is the error message I got on the clean install:

Traceback (most recent call last):
  File "/usr/lib/python2.7/threading.py", line 552, in __bootstrap_inner
    self.run()
  File "/usr/lib/python2.7/dist-packages/ws4py/manager.py", line 259, in run
    if not ws.once():
  File "/usr/lib/python2.7/dist-packages/ws4py/websocket.py", line 305, in once
    if not self.process(b):
  File "/usr/lib/python2.7/dist-packages/ws4py/websocket.py", line 377, in process
    self.received_message(s.message)
  File "/usr/local/lib/python2.7/dist-packages/mopidy/http/ws.py", line 70, in received_message
    self.send(response)
  File "/usr/lib/python2.7/dist-packages/ws4py/websocket.py", line 261, in send
    self._write(m)
  File "/usr/lib/python2.7/dist-packages/ws4py/websocket.py", line 243, in _write
    self.sock.sendall(b)
  File "/usr/lib/python2.7/socket.py", line 224, in meth
    return getattr(self._sock,name)(*args)
error: [Errno 32] Broken pipe
@adamcik

This comment has been minimized.

Member

adamcik commented Feb 6, 2014

Think I've figured this out. Added the following code so that I could trigger something similar without having to actually have a broken pipe. As the broken pipe case will typically happen when the device closes the socket and then we can't detect it until we try and write to it.

diff --git a/mopidy/http/ws.py b/mopidy/http/ws.py
index 4d7aa9a..d70a1a8 100644
--- a/mopidy/http/ws.py
+++ b/mopidy/http/ws.py
@@ -67,6 +67,9 @@ class WebSocketHandler(WebSocket):

         response = self.jsonrpc.handle_json(request)
         if response:
+            if 'spotify:track:26TlzkCLIdXKH5rTZJmWfn' in response:
+                import socket
+                raise socket.error(socket.errno.EPIPE, 'Broken pipe')
             self.send(response)
             logger.debug(
                 'Sent WebSocket message to %s:%d: %r',

With this in place, and playing an playlist/album with the "magic" track in it the error is raised and I experience the same problem you've had. So I think we just need to catch socket errors when sending, as ws4py doesn't do a good enough job of this currently.

@adamcik

This comment has been minimized.

Member

adamcik commented Feb 6, 2014

Also note that https://github.com/Lawouach/WebSocket-for-Python/blob/master/ws4py/websocket.py#L55 implies that we should be expecting send calls to raise socket errors and need to handle them ourselves. This expectation should have been documented in ws4py at the very least.

@woutervanwijk

This comment has been minimized.

Contributor

woutervanwijk commented Feb 6, 2014

That's good news! I could not have found that myself...

@adamcik

This comment has been minimized.

Member

adamcik commented Feb 6, 2014

If you try adding the following changes locally it hopefully can't be reproduced any more:

diff --git a/mopidy/http/ws.py b/mopidy/http/ws.py
index 4d7aa9a..f86e393 100644
--- a/mopidy/http/ws.py
+++ b/mopidy/http/ws.py
@@ -1,6 +1,7 @@
 from __future__ import unicode_literals

 import logging
+import socket

 import cherrypy
 from ws4py.websocket import WebSocket
@@ -67,7 +68,12 @@ class WebSocketHandler(WebSocket):

         response = self.jsonrpc.handle_json(request)
         if response:
-            self.send(response)
-            logger.debug(
-                'Sent WebSocket message to %s:%d: %r',
-                remote.ip, remote.port, response)
+            try:
+                self.send(response)
+                logger.debug(
+                    'Sent WebSocket message to %s:%d: %r',
+                    remote.ip, remote.port, response)
+            except socket.error as e:
+                logger.debug(
+                    'Failed WebSocket message to %s:%d: %r',
+                    remote.ip, remote.port, response)
@woutervanwijk

This comment has been minimized.

Contributor

woutervanwijk commented Feb 7, 2014

I think you've made my day! My first quick tests indicate that it's solved. If it is indeed, I will close this one.

@woutervanwijk

This comment has been minimized.

Contributor

woutervanwijk commented Feb 7, 2014

An observation: I think the error still occurs sometimes, then the interface hangs and the 'object disappeared' error is reported in the console, but after a few seconds, the connection is restored correctly. Maybe not completely correct, but it works for me. This should free the way for a new Musicbox with a fresh mopidy, browsing, etc... :))

@adamcik

This comment has been minimized.

Member

adamcik commented Feb 7, 2014

My current guess is that the wifi or whatever network you have is a bit lossy, and that we are loosing the client. The fix I proposed ensures that we don't crash the HTTP serving in mopidy when this happens. However, it does not fix the fact that the client looses it's connection and needs to reset to find the objects.

In other words the mopidy js code and/or the webclient need to be updated to handle this better. So please don't close this until we have actually committed the python side fix, and hopefully found something for the JS side.

@jodal

This comment has been minimized.

Member

jodal commented Feb 7, 2014

That may very well just be Mopidy.js reconnecting. The errors causing this issue still happens, only with @adamcik's patch they don't kill the server side. The WebSocket connection is still lost, and Mopidy.js' reconnection feature jumps in.

You can listen for the following events on the mopidy object to update your UI while we're reconnecting: state:online, state:offline, reconnectionPending, and reconnecting. To simulate the events, simply stop and start Mopidy while you have the web client open.

@jodal

This comment has been minimized.

Member

jodal commented Feb 7, 2014

@adamcik I guess the reconnection stuff in Mopidy.js should be good enough, and you simply forgot that we already had that feature? Or are you thinking of further measures to mitigate this in the client library?

@adamcik

This comment has been minimized.

Member

adamcik commented Feb 7, 2014

More if we could make the objects not disappear and queue up actions, or find some other smarter handling of this. Otherwise we just need to stress the importance of correct handling of offline events to avoid this problem in the docs.

@jodal jodal added this to the 0.18.2 milestone Feb 7, 2014

@adamcik

This comment has been minimized.

Member

adamcik commented Feb 7, 2014

Trick to trigger this without any code changes is refreshing a lot, once I a while you'll win a race and trigger this issue.

@adamcik adamcik closed this in 94fe38f Feb 7, 2014

@adamcik

This comment has been minimized.

Member

adamcik commented Feb 7, 2014

Found a second case that triggers this and inspected the ws4py code looking for more potentially problematic spots. However, we do need to file an upstream bug for this to get it fixed properly.

adamcik added a commit that referenced this issue Feb 7, 2014

@beniroquai

This comment has been minimized.

beniroquai commented Feb 10, 2014

I've the exact same problem. Is there a quick fix I could apply to a file using you soloution? I'm using GMusic Plugin as well. Mopidy works without it and I'm getting brocken Pipe Error when enabling it..Actually same log as above..

@adamcik

This comment has been minimized.

Member

adamcik commented Feb 10, 2014

You need a version of mopidy with 94fe38f, so you have to wait for 0.18.2 or apply the patch yourself.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment