Inconsistent unit test failures in control.controller

On occasion our unit tests that emit then listen for controller events fail
with...

  ======================================================================
  FAIL: test_events_get_received
  ----------------------------------------------------------------------
  Traceback (most recent call last):
    File "/usr/lib/python2.7/dist-packages/mock/mock.py", line 1305, in patched
      return func(*args, **keywargs)
    File "/srv/jenkins-workspace/workspace/stem-tor-ci/test/unit/control/controller.py", line 684, in test_events_get_received
      self.bw_listener.assert_called_once_with(BW_EVENT)
    File "/usr/lib/python2.7/dist-packages/mock/mock.py", line 947, in assert_called_once_with
      raise AssertionError(msg)
  AssertionError: Expected 'mock' to be called once. Called 0 times.

  ----------------------------------------------------------------------

The specific test varies, but it should always be one of our emit_event()
callers. This has caused nine jenkins test failures in the last three months
(so pretty noisy). Dave ran into this too...

  https://trac.torproject.org/projects/tor/ticket/27173

I can't reliably (or even frequently) reproduce this locally but I think I know
what's going on...

  * emit_event() adds an event to the queue via put(). This is a blocking call
    so we can be assured the event's in there.

  * emit_event() then calls set() on the event_notice condition so the
    Controller's event thread will process the event.

  * The controller's event thread calls get_nowait() on its event queue. This
    *ususally* gets the event we just inserted, but since this is get_nowait()
    rather than get() it's non-blocking, and may raise a queue.Empty instead.

  * When queue.Empty gets thrown we once again wait on the event_notice
    condition.

  * emit_event() then calls close() on its Controller which joins and
    terminates its threads. The close() method calls set() on event_noice to
    give it a *second* opportunity to get the event.

  * Once again, because we use get_nowait() there's a small chance we'll raise
    queue.Empty without processing the event.

  * The event thread then terminates with the enqueued event never being
    processed.

  * Finally, we get the assertion failure above.

This is actually a real bug that can cause Controller users to be highly
delayed or never receive an event. For instance...

  * Tor emits an event.

  * Our reader thread enqueues the event and calls set() on the condition to
    notify the event thread.

  * For the reasons mentioned above it fails to do so.

  * Because we use wait() without a timeout our event thread then resumes
    blocking, causing the event to not get another chance to be delivered until
    a second event comes along.

This sucks, and is pretty easy to remediate. Rather than waiting indefinitely
we should instead have our event thread periodically check re-check its own
queue for undelivered messages (picked 50 ms as a decent sounding balance
between responsiveness and load). Our test's emit_event() in turn now blocks
until the event is delivered.

Needless to say this is a long song and dance so quite possible I'm in the
wrong on something but this seems, both in theory and practice thus far, to be
a good step forward.

3 files changed, 7 insertions, 1 deletions

diff --git a/docs/change_log.rst b/docs/change_log.rst
index 9230350c..f47ec984 100644
--- a/docs/change_log.rst
+++ b/docs/change_log.rst
@@ -45,6 +45,10 @@ Unreleased
 The following are only available within Stem's `git repository
 <download.html>`_.
 
+ * **Controller**
+
+  * Controller events could fail to be delivered in a timely fashion (:trac:`27173`)
+
 .. _version_1.7:
 
 Version 1.7 (October 7th, 2018)
diff --git a/stem/control.py b/stem/control.py
index 2e893788..68873d76 100644
--- a/stem/control.py
+++ b/stem/control.py
@@ -966,6 +966,7 @@ class BaseController(object):
       try:
         event_message = self._event_queue.get_nowait()
         self._handle_event(event_message)
+        self._event_queue.task_done()
 
         # Attempt to finish processing enqueued events when our controller closes
 
@@ -978,7 +979,7 @@ class BaseController(object):
         if not self.is_alive():
           break
 
-        self._event_notice.wait()
+        self._event_notice.wait(0.05)
         self._event_notice.clear()
 
 
diff --git a/test/unit/control/controller.py b/test/unit/control/controller.py
index ed72fbe8..13d26c4b 100644
--- a/test/unit/control/controller.py
+++ b/test/unit/control/controller.py
@@ -866,6 +866,7 @@ class TestControl(unittest.TestCase):
           uncast_event = ControlMessage.from_str(event.raw_content())
           self.controller._event_queue.put(uncast_event)
           self.controller._event_notice.set()
+          self.controller._event_queue.join()  # block until the event is consumed
         finally:
           is_alive_mock.return_value = False
           self.controller._close()