From 320f5f30b35695adf1cb1254f26af3b87ec4d2a3 Mon Sep 17 00:00:00 2001 From: rl1987 Date: Sun, 4 Nov 2018 18:09:31 +0200 Subject: [PATCH 1/5] In test_rebind.py, log stuff with timestamps --- src/test/test_rebind.py | 13 +++++++++---- 1 file changed, 9 insertions(+), 4 deletions(-) diff --git a/src/test/test_rebind.py b/src/test/test_rebind.py index c63341a681..64eba14f05 100644 --- a/src/test/test_rebind.py +++ b/src/test/test_rebind.py @@ -1,6 +1,7 @@ from __future__ import print_function import errno +import logging import os import random import socket @@ -13,7 +14,7 @@ LOG_WAIT = 0.1 LOG_CHECK_LIMIT = LOG_TIMEOUT / LOG_WAIT def fail(msg): - print('FAIL') + logging.error('FAIL') sys.exit(msg) def try_connecting_to_socksport(): @@ -30,7 +31,7 @@ def wait_for_log(s): l = l.decode('utf8') if s in l: return - print('Tor logged: "{}", waiting for "{}"'.format(l.strip(), s)) + 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: @@ -55,6 +56,10 @@ def pick_random_port(): return port +logging.basicConfig(level=logging.DEBUG, + format='%(asctime)s.%(msecs)03d %(message)s', + datefmt='%Y-%m-%d %H:%M:%S') + if sys.hexversion < 0x02070000: fail("ERROR: unsupported Python version (should be >= 2.7)") @@ -108,13 +113,13 @@ try_connecting_to_socksport() control_socket.sendall('SIGNAL HALT\r\n'.encode('utf8')) wait_for_log('exiting cleanly') -print('OK') +logging.info('OK') try: tor_process.terminate() except OSError as e: if e.errno == errno.ESRCH: # errno 3: No such process # assume tor has already exited due to SIGNAL HALT - print("Tor has already exited") + logging.warn("Tor has already exited") else: raise From 0bb25931dc620fd4b96146d11144bee3754c077f Mon Sep 17 00:00:00 2001 From: rl1987 Date: Sun, 4 Nov 2018 19:01:00 +0200 Subject: [PATCH 2/5] Log everything from tor down to debug loglevel --- src/test/test_rebind.py | 1 + 1 file changed, 1 insertion(+) diff --git a/src/test/test_rebind.py b/src/test/test_rebind.py index 64eba14f05..dfd0ccbcb6 100644 --- a/src/test/test_rebind.py +++ b/src/test/test_rebind.py @@ -80,6 +80,7 @@ tor_path = sys.argv[1] tor_process = subprocess.Popen([tor_path, '-ControlPort', '127.0.0.1:{}'.format(control_port), '-SOCKSPort', '127.0.0.1:{}'.format(socks_port), + '-Log', 'debug stdout', '-FetchServerDescriptors', '0'], stdout=subprocess.PIPE, stderr=subprocess.PIPE) From 9bbf7ec3031a2597944e2df59b634ff77a36a3f8 Mon Sep 17 00:00:00 2001 From: rl1987 Date: Sun, 4 Nov 2018 19:10:40 +0200 Subject: [PATCH 3/5] Add changes file --- changes/ticket28229_diag | 3 +++ 1 file changed, 3 insertions(+) create mode 100644 changes/ticket28229_diag diff --git a/changes/ticket28229_diag b/changes/ticket28229_diag new file mode 100644 index 0000000000..cd02b81faa --- /dev/null +++ b/changes/ticket28229_diag @@ -0,0 +1,3 @@ + o Testing: + - Increase logging and tag all log entries with timestamps + in test_rebind.py. Provides diagnostics for issue 28229. From 4c4ed413ee5d865e46a5659c4f6b5b88f12f37b7 Mon Sep 17 00:00:00 2001 From: rl1987 Date: Tue, 13 Nov 2018 11:15:40 +0200 Subject: [PATCH 4/5] 1 ms. resolution for Tor logs --- src/test/test_rebind.py | 1 + 1 file changed, 1 insertion(+) diff --git a/src/test/test_rebind.py b/src/test/test_rebind.py index dfd0ccbcb6..cab6aafbb6 100644 --- a/src/test/test_rebind.py +++ b/src/test/test_rebind.py @@ -81,6 +81,7 @@ tor_process = subprocess.Popen([tor_path, '-ControlPort', '127.0.0.1:{}'.format(control_port), '-SOCKSPort', '127.0.0.1:{}'.format(socks_port), '-Log', 'debug stdout', + '-LogTimeGranularity', '1', '-FetchServerDescriptors', '0'], stdout=subprocess.PIPE, stderr=subprocess.PIPE) From 945c4dfda014724375e499afef77a9abd1449631 Mon Sep 17 00:00:00 2001 From: rl1987 Date: Tue, 13 Nov 2018 11:38:51 +0200 Subject: [PATCH 5/5] Also log a Tor log entry when it has a substring we are waiting for --- src/test/test_rebind.py | 1 + 1 file changed, 1 insertion(+) diff --git a/src/test/test_rebind.py b/src/test/test_rebind.py index cab6aafbb6..2215b42253 100644 --- a/src/test/test_rebind.py +++ b/src/test/test_rebind.py @@ -30,6 +30,7 @@ def wait_for_log(s): l = tor_process.stdout.readline() l = l.decode('utf8') 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