December 2018 - tor-commits - lists.torproject.org

[tor/maint-0.3.5] 1 ms. resolution for Tor logs
by nickm＠torproject.org 01 Dec '18

01 Dec '18

commit 4c4ed413ee5d865e46a5659c4f6b5b88f12f37b7 Author: rl1987 <rl1987(a)sdf.lonestar.org> Date: Tue Nov 13 11:15:40 2018 +0200 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 dfd0ccbcb..cab6aafbb 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)

1 0

[tor/maint-0.3.5] Log everything from tor down to debug loglevel
by nickm＠torproject.org 01 Dec '18

01 Dec '18

commit 0bb25931dc620fd4b96146d11144bee3754c077f Author: rl1987 <rl1987(a)sdf.lonestar.org> Date: Sun Nov 4 19:01:00 2018 +0200 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 64eba14f0..dfd0ccbcb 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)

1 0

[tor/maint-0.3.5] Also log a Tor log entry when it has a substring we are waiting for
by nickm＠torproject.org 01 Dec '18

01 Dec '18

commit 945c4dfda014724375e499afef77a9abd1449631 Author: rl1987 <rl1987(a)sdf.lonestar.org> Date: Tue Nov 13 11:38:51 2018 +0200 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 cab6aafbb..2215b4225 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

1 0

[tor/master] In test_rebind.py, log stuff with timestamps
by nickm＠torproject.org 01 Dec '18

01 Dec '18

commit 320f5f30b35695adf1cb1254f26af3b87ec4d2a3 Author: rl1987 <rl1987(a)sdf.lonestar.org> Date: Sun Nov 4 18:09:31 2018 +0200 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 c63341a68..64eba14f0 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

1 0

[tor/master] Add changes file
by nickm＠torproject.org 01 Dec '18

01 Dec '18

commit 9bbf7ec3031a2597944e2df59b634ff77a36a3f8 Author: rl1987 <rl1987(a)sdf.lonestar.org> Date: Sun Nov 4 19:10:40 2018 +0200 Add changes file --- changes/ticket28229_diag | 3 +++ 1 file changed, 3 insertions(+) diff --git a/changes/ticket28229_diag b/changes/ticket28229_diag new file mode 100644 index 000000000..cd02b81fa --- /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.

1 0

[tor/master] 1 ms. resolution for Tor logs
by nickm＠torproject.org 01 Dec '18

01 Dec '18

commit 4c4ed413ee5d865e46a5659c4f6b5b88f12f37b7 Author: rl1987 <rl1987(a)sdf.lonestar.org> Date: Tue Nov 13 11:15:40 2018 +0200 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 dfd0ccbcb..cab6aafbb 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)

1 0

[tor/master] Log everything from tor down to debug loglevel
by nickm＠torproject.org 01 Dec '18

01 Dec '18

commit 0bb25931dc620fd4b96146d11144bee3754c077f Author: rl1987 <rl1987(a)sdf.lonestar.org> Date: Sun Nov 4 19:01:00 2018 +0200 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 64eba14f0..dfd0ccbcb 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)

1 0

[tor/master] Also log a Tor log entry when it has a substring we are waiting for
by nickm＠torproject.org 01 Dec '18

01 Dec '18

commit 945c4dfda014724375e499afef77a9abd1449631 Author: rl1987 <rl1987(a)sdf.lonestar.org> Date: Tue Nov 13 11:38:51 2018 +0200 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 cab6aafbb..2215b4225 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

1 0

[tor/maint-0.3.5] Merge branch 'bug28229_diag_035' into maint-0.3.5
by nickm＠torproject.org 01 Dec '18

01 Dec '18

commit 11a91ef728b18f86cee4a56b946d7c6f1f7958ba Merge: e82023d2f 945c4dfda Author: Nick Mathewson <nickm(a)torproject.org> Date: Sat Dec 1 11:20:04 2018 -0500 Merge branch 'bug28229_diag_035' into maint-0.3.5 changes/ticket28229_diag | 3 +++ src/test/test_rebind.py | 16 ++++++++++++---- 2 files changed, 15 insertions(+), 4 deletions(-)

1 0

[tor/release-0.3.5] In test_rebind.py, log stuff with timestamps
by nickm＠torproject.org 01 Dec '18

01 Dec '18

commit 320f5f30b35695adf1cb1254f26af3b87ec4d2a3 Author: rl1987 <rl1987(a)sdf.lonestar.org> Date: Sun Nov 4 18:09:31 2018 +0200 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 c63341a68..64eba14f0 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

1 0