commit cf2b00d3f50f3421c3c22777113e25d5f7812e67 Author: teor <teor@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')