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.

2 files changed, 14 insertions, 7 deletions

diff --git a/changes/bug31837 b/changes/bug31837
new file mode 100644
index 0000000000..0f976edfe0
--- /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 45ad1c5469..30a587858f 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')