[tor-commits] [tor/maint-0.4.2] test/rebind: Make control formatting and log parsing more robust

[teor at torproject.org]

commit cf2b00d3f50f3421c3c22777113e25d5f7812e67
Author: teor <teor at torproject.org>
Date:   Tue Aug 6 01:33:14 2019 +1000

    test/rebind: Make control formatting and log parsing more robust
    
    * actually sleep when tor has not logged anything
    * log at debug level when waiting for tor to log something
    * backslash-replace bad UTF-8 characters in logs
    * format control messages as ASCII: tor does not accept UTF-8 control commands
    
    Fixes bug 31837; bugfix on 0.3.5.1-alpha.
---
 changes/bug31837        |  5 +++++
 src/test/test_rebind.py | 16 +++++++++-------
 2 files changed, 14 insertions(+), 7 deletions(-)

diff --git a/changes/bug31837 b/changes/bug31837
new file mode 100644
index 000000000..0f976edfe
--- /dev/null
+++ b/changes/bug31837
@@ -0,0 +1,5 @@
+  o Minor bugfixes (testing):
+    - When testing port rebinding, don't busy-wait for tor to log. Instead,
+      actually sleep for a short time before polling again. Also improve the
+      formatting of control commands and log messages.
+      Fixes bug 31837; bugfix on 0.3.5.1-alpha.
diff --git a/src/test/test_rebind.py b/src/test/test_rebind.py
index 45ad1c546..30a587858 100644
--- a/src/test/test_rebind.py
+++ b/src/test/test_rebind.py
@@ -31,15 +31,17 @@ def wait_for_log(s):
     cutoff = time.time() + LOG_TIMEOUT
     while time.time() < cutoff:
         l = tor_process.stdout.readline()
-        l = l.decode('utf8')
+        l = l.decode('utf8', 'backslashreplace')
         if s in l:
             logging.info('Tor logged: "{}"'.format(l.strip()))
             return
-        logging.info('Tor logged: "{}", waiting for "{}"'.format(l.strip(), s))
         # readline() returns a blank string when there is no output
         # avoid busy-waiting
-        if len(s) == 0:
+        if len(l) == 0:
+            logging.debug('Tor has not logged anything, waiting for "{}"'.format(s))
             time.sleep(LOG_WAIT)
+        else:
+            logging.info('Tor logged: "{}", waiting for "{}"'.format(l.strip(), s))
     fail('Could not find "{}" in logs after {} seconds'.format(s, LOG_TIMEOUT))
 
 def pick_random_port():
@@ -119,18 +121,18 @@ if control_socket.connect_ex(('127.0.0.1', control_port)):
     tor_process.terminate()
     fail('Cannot connect to ControlPort')
 
-control_socket.sendall('AUTHENTICATE \r\n'.encode('utf8'))
-control_socket.sendall('SETCONF SOCKSPort=0.0.0.0:{}\r\n'.format(socks_port).encode('utf8'))
+control_socket.sendall('AUTHENTICATE \r\n'.encode('ascii'))
+control_socket.sendall('SETCONF SOCKSPort=0.0.0.0:{}\r\n'.format(socks_port).encode('ascii'))
 wait_for_log('Opened Socks listener')
 
 try_connecting_to_socksport()
 
-control_socket.sendall('SETCONF SOCKSPort=127.0.0.1:{}\r\n'.format(socks_port).encode('utf8'))
+control_socket.sendall('SETCONF SOCKSPort=127.0.0.1:{}\r\n'.format(socks_port).encode('ascii'))
 wait_for_log('Opened Socks listener')
 
 try_connecting_to_socksport()
 
-control_socket.sendall('SIGNAL HALT\r\n'.encode('utf8'))
+control_socket.sendall('SIGNAL HALT\r\n'.encode('ascii'))
 
 wait_for_log('exiting cleanly')
 logging.info('OK')