commit 7d639f217671fcbe44945f07c5e81b250adea625 Author: Damian Johnson atagar@torproject.org Date: Thu Sep 21 10:11:42 2017 -0700

Close control socket faster when under load

When receiving a high volume of traffic (such as DEBUG events on a busy relay) our controller can take seconds or even minutes to close. This is because we send a QUIT signal, then wait for the response which is stuck behind potentially thousands of events.

From what I can tell there's little point in issuing a QUIT so dropping that, and setting a time limit for processing backlogged events. --- docs/change_log.rst | 1 + stem/control.py | 25 ++++++++++++++++--------- stem/socket.py | 2 +- 3 files changed, 18 insertions(+), 10 deletions(-)

diff --git a/docs/change_log.rst b/docs/change_log.rst index 8d9c10aa..2e421c4f 100644 --- a/docs/change_log.rst +++ b/docs/change_log.rst @@ -62,6 +62,7 @@ The following are only available within Stem's `git repository * Added :func:`~stem.manual.database` to get a cursor for the manual cache * Failed to parse torrcs without a port on ipv6 exit policy entries * Resilient to 'Tor' prefix in 'GETINFO version' result (:spec:`c5ff1b1`) + * Closing controller connection faster when under heavy event load * More succinct trace level logging

* **Descriptors** diff --git a/stem/control.py b/stem/control.py index fd5f9f87..ef9919be 100644 --- a/stem/control.py +++ b/stem/control.py @@ -281,6 +281,11 @@ import stem.version from stem import UNDEFINED, CircStatus, Signal from stem.util import str_type, log

+# When closing the controller we attempt to finish processing enqueued events, +# but if it takes longer than this we terminate. + +EVENTS_LISTENING_TIMEOUT = 0.1 + # state changes a control socket can have

State = stem.util.enum.Enum('INIT', 'RESET', 'CLOSED') @@ -957,10 +962,20 @@ class BaseController(object): socket. """

+ socket_closed_at = None + while True: try: event_message = self._event_queue.get_nowait() self._handle_event(event_message) + + # Attempt to finish processing enqueued events when our controller closes + + if not self.is_alive(): + if not socket_closed_at: + socket_closed_at = time.time() + elif time.time() - socket_closed_at > EVENTS_LISTENING_TIMEOUT: + break except queue.Empty: if not self.is_alive(): break @@ -1057,15 +1072,7 @@ class Controller(BaseController): self.add_event_listener(_confchanged_listener, EventType.CONF_CHANGED)

def close(self): - # making a best-effort attempt to quit before detaching the socket - if self.is_authenticated(): - try: - self.msg('QUIT') - except: - pass - - self.clear_cache() - + self.clear_cache() super(Controller, self).close()

def authenticate(self, *args, **kwargs): diff --git a/stem/socket.py b/stem/socket.py index eddbfe58..ef2d77c7 100644 --- a/stem/socket.py +++ b/stem/socket.py @@ -573,7 +573,7 @@ def recv_message(control_file): divider = stem.util.str_tools._to_unicode(divider)

# Most controller responses are single lines, in which case we don't need - # some overhead. + # so much overhead.

if first_line: if divider == ' ':