EOT changes makes "next" deadlock Mopidy

[jodal]

To reproduce:

1. Load an album or a playlist into the tracklist
2. Start playing the first track
3. Go to the next track

Result: Audio stops, everything becomes unresponsive.

[jodal]

I think this is caused by core.playback.stop() blocking forever on backend.playback.stop() to return.

I'm experiencing this playing from Spotify. I haven't tried with local music.

[jodal]

I can still reproduce this on develop, now using another machine. Using our beloved debug thread, this is quite debuggable.

The MPD session blocks waiting for core:

DEBUG    2013-01-07 22:02:28,687 [31764:DebugThread] mopidy.utils.process
  Current state of MpdSession-27 (140580973696768):
  File "/usr/lib/python2.7/threading.py", line 525, in __bootstrap
    self.__bootstrap_inner()
  File "/usr/lib/python2.7/threading.py", line 552, in __bootstrap_inner
    self.run()
  File "/usr/lib/python2.7/threading.py", line 505, in run
    self.__target(*self.__args, **self.__kwargs)
  File "/usr/lib/pymodules/python2.7/pykka/actor.py", line 194, in _actor_loop
    response = self._handle_receive(message)
  File "/usr/lib/pymodules/python2.7/pykka/actor.py", line 274, in _handle_receive
    return self.on_receive(message)
  File "/home/jodal/dev/mopidy/mopidy/utils/network.py", line 354, in on_receive
    self.on_line_received(line)
  File "/home/jodal/dev/mopidy/mopidy/frontends/mpd/session.py", line 32, in on_line_received
    response = self.dispatcher.handle_request(line)
  File "/home/jodal/dev/mopidy/mopidy/frontends/mpd/dispatcher.py", line 45, in handle_request
    return self._call_next_filter(request, response, filter_chain)
  File "/home/jodal/dev/mopidy/mopidy/frontends/mpd/dispatcher.py", line 66, in _call_next_filter
    return next_filter(request, response, filter_chain)
  File "/home/jodal/dev/mopidy/mopidy/frontends/mpd/dispatcher.py", line 74, in _catch_mpd_ack_errors_filter
    return self._call_next_filter(request, response, filter_chain)
  File "/home/jodal/dev/mopidy/mopidy/frontends/mpd/dispatcher.py", line 66, in _call_next_filter
    return next_filter(request, response, filter_chain)
  File "/home/jodal/dev/mopidy/mopidy/frontends/mpd/dispatcher.py", line 84, in _authenticate_filter
    return self._call_next_filter(request, response, filter_chain)
  File "/home/jodal/dev/mopidy/mopidy/frontends/mpd/dispatcher.py", line 66, in _call_next_filter
    return next_filter(request, response, filter_chain)
  File "/home/jodal/dev/mopidy/mopidy/frontends/mpd/dispatcher.py", line 105, in _command_list_filter
    response = self._call_next_filter(request, response, filter_chain)
  File "/home/jodal/dev/mopidy/mopidy/frontends/mpd/dispatcher.py", line 66, in _call_next_filter
    return next_filter(request, response, filter_chain)
  File "/home/jodal/dev/mopidy/mopidy/frontends/mpd/dispatcher.py", line 134, in _idle_filter
    response = self._call_next_filter(request, response, filter_chain)
  File "/home/jodal/dev/mopidy/mopidy/frontends/mpd/dispatcher.py", line 66, in _call_next_filter
    return next_filter(request, response, filter_chain)
  File "/home/jodal/dev/mopidy/mopidy/frontends/mpd/dispatcher.py", line 147, in _add_ok_filter
    response = self._call_next_filter(request, response, filter_chain)
  File "/home/jodal/dev/mopidy/mopidy/frontends/mpd/dispatcher.py", line 66, in _call_next_filter
    return next_filter(request, response, filter_chain)
  File "/home/jodal/dev/mopidy/mopidy/frontends/mpd/dispatcher.py", line 159, in _call_handler_filter
    response = self._format_response(self._call_handler(request))
  File "/home/jodal/dev/mopidy/mopidy/frontends/mpd/dispatcher.py", line 167, in _call_handler
    return handler(self.context, **kwargs)
  File "/home/jodal/dev/mopidy/mopidy/frontends/mpd/protocol/playback.py", line 95, in next_
    return context.core.playback.next().get()
  File "/usr/lib/pymodules/python2.7/pykka/future.py", line 109, in get
    self._data = self._queue.get(True, timeout)
  File "/usr/lib/python2.7/Queue.py", line 168, in get
    self.not_empty.wait()
  File "/usr/lib/python2.7/threading.py", line 244, in wait
    waiter.acquire()

Core waits for the backend:

DEBUG    2013-01-07 22:02:28,689 [31764:DebugThread] mopidy.utils.process
  Current state of Core-7 (140582852216576):
  File "/usr/lib/python2.7/threading.py", line 525, in __bootstrap
    self.__bootstrap_inner()
  File "/usr/lib/python2.7/threading.py", line 552, in __bootstrap_inner
    self.run()
  File "/usr/lib/python2.7/threading.py", line 505, in run
    self.__target(*self.__args, **self.__kwargs)
  File "/usr/lib/pymodules/python2.7/pykka/actor.py", line 194, in _actor_loop
    response = self._handle_receive(message)
  File "/usr/lib/pymodules/python2.7/pykka/actor.py", line 265, in _handle_receive
    return callee(*message['args'], **message['kwargs'])
  File "/home/jodal/dev/mopidy/mopidy/core/playback.py", line 368, in next
    self.change_track(self.tl_track_at_next)
  File "/home/jodal/dev/mopidy/mopidy/core/playback.py", line 310, in change_track
    self.stop()
  File "/home/jodal/dev/mopidy/mopidy/core/playback.py", line 481, in stop
    if not backend or backend.playback.stop().get():
  File "/usr/lib/pymodules/python2.7/pykka/future.py", line 109, in get
    self._data = self._queue.get(True, timeout)
  File "/usr/lib/python2.7/Queue.py", line 168, in get
    self.not_empty.wait()
  File "/usr/lib/python2.7/threading.py", line 244, in wait
    waiter.acquire()

The Spotify backend waits for audio:

DEBUG    2013-01-07 22:02:28,692 [31764:DebugThread] mopidy.utils.process
  Current state of SpotifyBackend-5 (140583101007616):
  File "/usr/lib/python2.7/threading.py", line 525, in __bootstrap
    self.__bootstrap_inner()
  File "/usr/lib/python2.7/threading.py", line 552, in __bootstrap_inner
    self.run()
  File "/usr/lib/python2.7/threading.py", line 505, in run
    self.__target(*self.__args, **self.__kwargs)
  File "/usr/lib/pymodules/python2.7/pykka/actor.py", line 194, in _actor_loop
    response = self._handle_receive(message)
  File "/usr/lib/pymodules/python2.7/pykka/actor.py", line 265, in _handle_receive
    return callee(*message['args'], **message['kwargs'])
  File "/home/jodal/dev/mopidy/mopidy/backends/spotify/playback.py", line 69, in stop
    return super(SpotifyPlaybackProvider, self).stop()
  File "/home/jodal/dev/mopidy/mopidy/backends/base.py", line 172, in stop
    return self.audio.stop_playback().get()
  File "/usr/lib/pymodules/python2.7/pykka/future.py", line 109, in get
    self._data = self._queue.get(True, timeout)
  File "/usr/lib/python2.7/Queue.py", line 168, in get
    self.not_empty.wait()
  File "/usr/lib/python2.7/threading.py", line 244, in wait
    waiter.acquire()

Audio is in the middle of calling it's about to finish callback, and are thus waiting on core, biting it's own tail. Deadlock is a fact.

DEBUG    2013-01-07 22:02:28,696 [31764:DebugThread] mopidy.utils.process
  Current state of Audio-2 (140583131789056):
  File "/usr/lib/python2.7/threading.py", line 525, in __bootstrap
    self.__bootstrap_inner()
  File "/usr/lib/python2.7/threading.py", line 552, in __bootstrap_inner
    self.run()
  File "/usr/lib/python2.7/threading.py", line 505, in run
    self.__target(*self.__args, **self.__kwargs)
  File "/usr/lib/pymodules/python2.7/pykka/actor.py", line 194, in _actor_loop
    response = self._handle_receive(message)
  File "/usr/lib/pymodules/python2.7/pykka/actor.py", line 265, in _handle_receive
    return callee(*message['args'], **message['kwargs'])
  File "/home/jodal/dev/mopidy/mopidy/audio/actor.py", line 416, in stop_playback
    return self._set_state(gst.STATE_NULL)
  File "/home/jodal/dev/mopidy/mopidy/audio/actor.py", line 439, in _set_state
    result = self._playbin.set_state(state)
  File "/home/jodal/dev/mopidy/mopidy/audio/actor.py", line 111, in _on_about_to_finish
    self._end_of_track_callback()
  File "/home/jodal/dev/mopidy/mopidy/core/actor.py", line 52, in <lambda>
    lambda: self.actor_ref.proxy().playback.on_end_of_track().get())
  File "/usr/lib/pymodules/python2.7/pykka/actor.py", line 461, in proxy
    return _ActorProxy(self)
  File "/usr/lib/pymodules/python2.7/pykka/proxy.py", line 99, in __init__
    self._known_attrs = self._get_attributes()
  File "/usr/lib/pymodules/python2.7/pykka/proxy.py", line 111, in _get_attributes
    attr = self._actor._get_attribute_from_path(attr_path)
  File "/usr/lib/pymodules/python2.7/pykka/actor.py", line 296, in _get_attribute_from_path
    attr = getattr(attr, attr_name)
  File "/home/jodal/dev/mopidy/mopidy/core/actor.py", line 56, in get_uri_schemes
    results = pykka.get_all(futures)
  File "/usr/lib/pymodules/python2.7/pykka/future.py", line 147, in get_all
    return [future.get(timeout=timeout) for future in futures]
  File "/usr/lib/pymodules/python2.7/pykka/future.py", line 109, in get
    self._data = self._queue.get(True, timeout)
  File "/usr/lib/python2.7/Queue.py", line 168, in get
    self.not_empty.wait()
  File "/usr/lib/python2.7/threading.py", line 244, in wait
    waiter.acquire()

[jodal]

The reason the about-to-finish callback works for EOT is because that is caused by audio not having more data to play, and not a blocking call all the way down from a frontend through core.

I guess the solution here is to break the block chain. core.playback.stop() doesn't really need to block on the rest of the chain if only we'd implement #234 so that the playback state would be updated when audio is done with it's part.

Another solution would maybe be to go to consider reimplementing core.playback.change_track() to not stop playback now when we got a backend.playback.change_track()?

[DanMeakin]

I have been experiencing the same problem as jodal. Is there a fix on the way for this? It unfortunately makes Mopidy unusable.

Alternatively, is there a way around the problem that anyone is aware of?

[jodal]

The solution until we're done with a cleanup of core.playback is to use 0.11.1/master.

[jodal]

The EOT changes have now been reverted out of the develop branch. A new pull request #346 with the EOT changes has been opened. This issue is still relevant for that pull request.

[jodal]

I'm closing this issue as the code causing it was reverted 7 months ago, and we've now closed the pull request which would reintroduce the changes in a fixed form.