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

MPD server hangs after receiving "close" command #150

Closed
raugturi opened this Issue May 16, 2012 · 10 comments

Comments

3 participants
@raugturi

raugturi commented May 16, 2012

I am using xmobar-0.15 with MPD support to get the status of the currently playing track. It in turn uses libmpd-0.7.2.

Whenever I do this, shortly after the first time it connects to mopidy all other connections to mopidy's MPD server are lost. Any further attempts to connect to mopidy (via ncmpcpp or another xmobar session) timeout.

Here is the debug log.

It appears to happen after the 'close' command is issued by the xmobar client. The line that crashes is line 151 of mopidy/utils/network.py. I can modify the dispatcher to ignore the close command or comment out the following try/except clause on lines 150-153 and it stops crashing:

    try:
        self.actor_ref.stop()
    except ActorDeadError:
        pass

self.actor_ref.stop() is not throwing any exception.

@jodal

This comment has been minimized.

Member

jodal commented May 21, 2012

My theory is that the client sends close to Mopidy, and then close the socket before it receives the OK from Mopidy.

@adamcik Does this sound like a possible explanation, or should the network server handle that nicely?

@adamcik

This comment has been minimized.

Member

adamcik commented May 21, 2012

Not sure of the top of my head. If this is what happens we should be able to test it easily enough. We could also look into adding unit tests that actually setup local sockets and run tests for cases like this.

@adamcik

This comment has been minimized.

Member

adamcik commented Sep 8, 2012

def test():
    s = socket.socket()
    s.connect(('', 6600))
    s.send('close\n')
    s.shutdown(socket.SHUT_RDWR)
    s.close()

Does indeed tickle this bug.

@adamcik

This comment has been minimized.

Member

adamcik commented Sep 8, 2012


DEBUG    2012-09-09 00:49:51,702 [5310:MainThread] mopidy.utils.server
  Client most likely disconnected.
INFO     2012-09-09 00:49:51,703 [5310:PykkaActorThread-4] mopidy.frontends.mpd
  New MPD connection from [::ffff:127.0.0.1]:52211
DEBUG    2012-09-09 00:49:51,705 [5310:PykkaActorThread-4] mopidy.frontends.mpd
  Request from [::ffff:127.0.0.1]:52211 to urn:uuid:44f47b4f-2b5d-467d-80a2-b72310f2a446: close
DEBUG    2012-09-09 00:49:51,773 [5310:PykkaActorThread-4] mopidy.utils.server
  Already stopping: Actor is shutting down.
DEBUG    2012-09-09 00:49:51,774 [5310:PykkaActorThread-4] mopidy.frontends.mpd
  Response to [::ffff:127.0.0.1]:52211 from urn:uuid:44f47b4f-2b5d-467d-80a2-b72310f2a446: OK
DEBUG    2012-09-09 00:49:51,774 [5310:PykkaActorThread-4] mopidy.utils.server
  Already stopping: Unexpected client error: [Errno 32] Broken pipe
@adamcik

This comment has been minimized.

Member

adamcik commented Sep 8, 2012

Doing a while true loop for the test case above seems to be best way to trigger this.

@adamcik

This comment has been minimized.

Member

adamcik commented Sep 9, 2012

As far as I can tell this is a race condition caused by bad interaction with actors going on from inside and outside the actor thread. I have a workaround where the close() called on the protocol instance just shuts down the socket instead of stopping the actor. This works around the issue by causing an error in the event loop and then our code in the main gobject thread stops the actor without any race conditions.

Following output produced via sys/threading.settrace shows the flow of events leading to mopidy becoming unresponsive.

...
MainThread: handle_connection() .../mopidy/utils/network.py:72
MainThread: accept_connection() .../mopidy/utils/network.py:84
MainThread: maximum_connections_exceeded() .../mopidy/utils/network.py:92
MainThread: number_of_connections() .../mopidy/utils/network.py:96
MainThread: init_connection() .../mopidy/utils/network.py:107
MainThread: __init__() .../mopidy/utils/network.py:120
MainThread: __init__() .../mopidy/frontends/mpd/__init__.py:77
MainThread: __init__() .../mopidy/utils/network.py:301
MainThread: __init__() .../mopidy/frontends/mpd/dispatcher.py:31
MainThread: __init__() .../mopidy/frontends/mpd/dispatcher.py:231
MainThread: enable_recv() .../mopidy/utils/network.py:201
MainThread: enable_timeout() .../mopidy/utils/network.py:185
MainThread: disable_timeout() .../mopidy/utils/network.py:194
MainThread: recv_callback() .../mopidy/utils/network.py:236
MainThread: recv_callback() .../mopidy/utils/network.py:236
MainThread: stop() .../mopidy/utils/network.py:143
PykkaActorThread-4: on_start() .../mopidy/frontends/mpd/__init__.py:81
PykkaActorThread-4: host() .../mopidy/utils/network.py:312
PykkaActorThread-4: port() .../mopidy/utils/network.py:316
INFO     New MPD connection from [::ffff:127.0.0.1]:56462
PykkaActorThread-4: send_lines() .../mopidy/utils/network.py:386
PykkaActorThread-4: join_lines() .../mopidy/utils/network.py:381
PykkaActorThread-4: encode() .../mopidy/utils/network.py:355
PykkaActorThread-4: queue_send() .../mopidy/utils/network.py:166
PykkaActorThread-4: send() .../mopidy/utils/network.py:174
PykkaActorThread-4: on_receive() .../mopidy/utils/network.py:328
PykkaActorThread-4: disable_timeout() .../mopidy/utils/network.py:194
PykkaActorThread-4: parse_lines() .../mopidy/utils/network.py:348
PykkaActorThread-4: decode() .../mopidy/frontends/mpd/__init__.py:101
PykkaActorThread-4: decode() .../mopidy/utils/network.py:368
PykkaActorThread-4: on_line_received() .../mopidy/frontends/mpd/__init__.py:85
PykkaActorThread-4: host() .../mopidy/utils/network.py:312
PykkaActorThread-4: port() .../mopidy/utils/network.py:316
PykkaActorThread-4: handle_request() .../mopidy/frontends/mpd/dispatcher.py:38
PykkaActorThread-4: _call_next_filter() .../mopidy/frontends/mpd/dispatcher.py:68
PykkaActorThread-4: _catch_mpd_ack_errors_filter() .../mopidy/frontends/mpd/dispatcher.py:78
PykkaActorThread-4: _call_next_filter() .../mopidy/frontends/mpd/dispatcher.py:68
PykkaActorThread-4: _authenticate_filter() .../mopidy/frontends/mpd/dispatcher.py:89
PykkaActorThread-4: __getattr__() .../mopidy/utils/settings.py:47
PykkaActorThread-4: _is_setting() .../mopidy/utils/settings.py:37
PykkaActorThread-4: current() .../mopidy/utils/settings.py:40
PykkaActorThread-4: current() .../mopidy/utils/settings.py:40
PykkaActorThread-4: _call_next_filter() .../mopidy/frontends/mpd/dispatcher.py:68
PykkaActorThread-4: _command_list_filter() .../mopidy/frontends/mpd/dispatcher.py:108
PykkaActorThread-4: _is_receiving_command_list() .../mopidy/frontends/mpd/dispatcher.py:120
PykkaActorThread-4: _call_next_filter() .../mopidy/frontends/mpd/dispatcher.py:68
PykkaActorThread-4: _idle_filter() .../mopidy/frontends/mpd/dispatcher.py:131
PykkaActorThread-4: _is_currently_idle() .../mopidy/frontends/mpd/dispatcher.py:148
PykkaActorThread-4: _is_currently_idle() .../mopidy/frontends/mpd/dispatcher.py:148
PykkaActorThread-4: _call_next_filter() .../mopidy/frontends/mpd/dispatcher.py:68
PykkaActorThread-4: _add_ok_filter() .../mopidy/frontends/mpd/dispatcher.py:154
PykkaActorThread-4: _call_next_filter() .../mopidy/frontends/mpd/dispatcher.py:68
PykkaActorThread-4: _call_handler_filter() .../mopidy/frontends/mpd/dispatcher.py:166
PykkaActorThread-4: _call_handler() .../mopidy/frontends/mpd/dispatcher.py:174
PykkaActorThread-4: _find_handler() .../mopidy/frontends/mpd/dispatcher.py:178
PykkaActorThread-4: close() .../mopidy/frontends/mpd/protocol/connection.py:6
PykkaActorThread-4: close() .../mopidy/frontends/mpd/__init__.py:109
PykkaActorThread-4: on_stop() .../mopidy/utils/network.py:344
PykkaActorThread-4: stop() .../mopidy/utils/network.py:143
PykkaActorThread-4: _format_response() .../mopidy/frontends/mpd/dispatcher.py:189
PykkaActorThread-4: _listify_result() .../mopidy/frontends/mpd/dispatcher.py:195
PykkaActorThread-4: _call_next_filter() .../mopidy/frontends/mpd/dispatcher.py:68
PykkaActorThread-4: _has_error() .../mopidy/frontends/mpd/dispatcher.py:160
PykkaActorThread-4: _is_currently_idle() .../mopidy/frontends/mpd/dispatcher.py:148
PykkaActorThread-4: _is_receiving_command_list() .../mopidy/frontends/mpd/dispatcher.py:120
PykkaActorThread-4: _is_processing_command_list() .../mopidy/frontends/mpd/dispatcher.py:124
PykkaActorThread-4: host() .../mopidy/utils/network.py:312
PykkaActorThread-4: port() .../mopidy/utils/network.py:316
PykkaActorThread-4: indent() .../mopidy/utils/log.py:48
PykkaActorThread-4: send_lines() .../mopidy/utils/network.py:386
PykkaActorThread-4: join_lines() .../mopidy/utils/network.py:381
PykkaActorThread-4: encode() .../mopidy/utils/network.py:355
PykkaActorThread-4: queue_send() .../mopidy/utils/network.py:166
PykkaActorThread-4: send() .../mopidy/utils/network.py:174
PykkaActorThread-4: stop() .../mopidy/utils/network.py:143
PykkaActorThread-4: parse_lines() .../mopidy/utils/network.py:353
PykkaActorThread-4: enable_timeout() .../mopidy/utils/network.py:185
PykkaActorThread-4: disable_timeout() .../mopidy/utils/network.py:194
@jodal

This comment has been minimized.

Member

jodal commented Sep 9, 2012

Would being able to stop the actor through its actor reference and thus through its inbox solve this?

I.e. being able to do self.ref.stop() instead of self.stop().

@adamcik

This comment has been minimized.

Member

adamcik commented Sep 9, 2012

That would probably do the trick, alternative would be that self.stop() post a message on the queue and that the actual work be moved to self._stop() or something like that.

@adamcik

This comment has been minimized.

Member

adamcik commented Sep 9, 2012

I tried switching to actor.ActorRef(self).stop() which did not seem to fix any ting :/

@adamcik

This comment has been minimized.

Member

adamcik commented Sep 9, 2012

Sweet, just figured this out. Problem is that the self.actor_ref.stop() in the network code blocks and never gets an answer, thus blocking the gobject loop. This was on my list of suspects, but the debugging tricks I was using where not sufficient to show that this was the problem. Changing to ``self.actor_ref.stop(block=False)` fixes this completely.

So as for debugging this, my first attempts where just using the debug log, which is useless, then using sys.settrace which is better, but still useless. Final solution was a traceback dumper thread that abused sys._current_frames() and traceback.extract_stack() to dump the tracebacks for active threads every once in a while. With this input seeing the problem was no challenge at all.

I'm thinking at the very least I want to add this debug helper somewhere under utils as pulling it in as long as we have threads for debugging might come in handy again. The more fancy approach would be attaching this to SIGUSR1 and using it to trigger traceback dumps at any time.

Thread: MainThread (-1216686400)
File: "/usr/lib/python2.6/runpy.py", line 122, in _run_module_as_main
 "__main__", fname, loader, pkg_name)
File: "/usr/lib/python2.6/runpy.py", line 34, in _run_code
 exec code in run_globals
File: ".../mopidy/__main__.py", line 180, in <module>
 main()
File: ".../mopidy/__main__.py", line 59, in main
 loop.run()
File: ".../mopidy/utils/network.py", line 249, in recv_callback
 self.stop(u'Client most likely disconnected.')
File: ".../mopidy/utils/network.py", line 153, in stop
 self.actor_ref.stop()
File: ".../virtualenv/lib/python2.6/site-packages/pykka/actor.py", line 470, in stop
 self.ask({'command': 'pykka_stop'}, block, timeout)
File: ".../virtualenv/lib/python2.6/site-packages/pykka/actor.py", line 444, in ask
 return future.get(timeout=timeout)
File: ".../virtualenv/lib/python2.6/site-packages/pykka/future.py", line 106, in get
 self._data = self._queue.get(True, timeout)
File: "/usr/lib/python2.6/Queue.py", line 168, in get
 self.not_empty.wait()
File: "/usr/lib/python2.6/threading.py", line 239, in wait
 waiter.acquire()

@adamcik adamcik closed this in ab7d0c4 Sep 9, 2012

adamcik added a commit that referenced this issue Sep 9, 2012

@ghost ghost assigned adamcik Sep 16, 2012

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