[tor-commits] [stem/master] Lowering logging about undelivered messages to the info level

[atagar at torproject.org]

commit 207dba02d6adcf794b19e00b330548348c950878
Author: Damian Johnson <atagar at torproject.org>
Date:   Tue Mar 18 09:48:50 2014 -0700

    Lowering logging about undelivered messages to the info level
    
    Our BaseController's test_msg_repeatedly integ test hammers the holy bejezus
    out of our controller socket in the hope of triggering exotic concurrency
    issues that might lead to issues like deadlock. This has been an impressively
    great test at ferreting out exotic issues and this is no different. Our Jenkins
    tests frequently log...
    
      03/12/2014 15:37:57 [NOTICE] BUG: the msg() function failed to deliver a
        response: Authentication required.
    
    After a couple hours of looking into this I gotta admit that I'm frustrated by
    the delicacy of our message handling. It works great in practice, but in theory
    issues such as socket errors or edge cases can cause undelivered messages.
    
    In this case rapidly connecting and closing the socket while simultaneously
    communicating on it causes the socket's recv() to occasionally raise
    exceptions. These exceptions are reported to callers, leaving enqueued messages
    that end up being undelivered (logging this notice).
    
    After much head scratching and digging into our socket class I've come to the
    realization that this is about as good as it's gonna get. If we use our recv
    queue to communicate *both* messages and exceptions then it is to be expected
    that exceptions can sometimes result in undelivered messages.
    
    Lowering the severity of the log message appropriately.
---
 stem/control.py |   19 +++++++++++++++----
 1 file changed, 15 insertions(+), 4 deletions(-)

diff --git a/stem/control.py b/stem/control.py
index 4d7f5b3..0d91587 100644
--- a/stem/control.py
+++ b/stem/control.py
@@ -346,9 +346,20 @@ class BaseController(object):
       #
       # - This is a leftover response for a msg() call. We can't tell who an
       #   exception was earmarked for, so we only know that this was the case
-      #   if it's a ControlMessage. This should not be possible and indicates
-      #   a stem bug. This deserves a NOTICE level log message since it
-      #   indicates that one of our callers didn't get their reply.
+      #   if it's a ControlMessage.
+      #
+      #   This is the most concerning situation since it indicates that one of
+      #   our callers didn't get their reply. However, this is still a
+      #   perfectly viable use case. For instance...
+      #
+      #   1. We send a request.
+      #   2. The reader thread encounters an exception, for instance a socket
+      #      error. We enqueue the exception.
+      #   3. The reader thread receives the reply.
+      #   4. We raise the socket error, and have an undelivered message.
+      #
+      #   Thankfully this only seems to arise in edge cases around rapidly
+      #   closing/reconnecting the socket.
 
       while not self._reply_queue.empty():
         try:
@@ -361,7 +372,7 @@ class BaseController(object):
           elif isinstance(response, stem.ControllerError):
             log.info("Socket experienced a problem (%s)" % response)
           elif isinstance(response, stem.response.ControlMessage):
-            log.notice("BUG: the msg() function failed to deliver a response: %s" % response)
+            log.info("Failed to deliver a response: %s" % response)
         except Queue.Empty:
           # the empty() method is documented to not be fully reliable so this
           # isn't entirely surprising