commit d92936cb2fb6ca5d2f3065e28ec33c7c1c87301f Author: Damian Johnson atagar@torproject.org Date: Wed Jun 5 14:21:37 2019 -0700
Testing '--log-file' argument
Argument so our tests log to a given file rather than stdout. Travis limits the amount of content stdout can receive, so we need this because trace logging with our RUN_ALL target is highly volumous.
https://trac.torproject.org/projects/tor/ticket/30675
That said, good argument to have regardless. --- run_tests.py | 26 +++++++++++++++++++++++--- stem/descriptor/remote.py | 2 +- stem/util/log.py | 13 +++++++++---- test/arguments.py | 5 ++++- test/output.py | 2 +- test/settings.cfg | 2 ++ 6 files changed, 40 insertions(+), 10 deletions(-)
diff --git a/run_tests.py b/run_tests.py index 088d3f62..ef31a05e 100755 --- a/run_tests.py +++ b/run_tests.py @@ -8,6 +8,7 @@ Runs unit and integration tests. For usage information run this with '--help'.
import errno import importlib +import logging import multiprocessing import os import signal @@ -233,10 +234,20 @@ def main(): test.task.PYCODESTYLE_TASK if not args.specific_test else None, )
- # buffer that we log messages into so they can be printed after a test has finished + # Test logging. If '--log-file' is provided we log to that location, + # otherwise we buffer messages and log to stdout after its test completes.
- logging_buffer = stem.util.log.LogBuffer(args.logging_runlevel) - stem.util.log.get_logger().addHandler(logging_buffer) + logging_buffer = None + + if args.logging_runlevel: + if args.logging_path: + handler = logging.FileHandler(args.logging_path, mode = 'w') + handler.setLevel(stem.util.log.logging_level(args.logging_runlevel)) + handler.setFormatter(stem.util.log.FORMATTER) + else: + handler = logging_buffer = stem.util.log.LogBuffer(args.logging_runlevel) + + stem.util.log.get_logger().addHandler(handler)
# filters for how testing output is displayed
@@ -399,6 +410,12 @@ def _print_static_issues(static_check_issues):
def _run_test(args, test_class, output_filters): + # When logging to a file we don't have stdout's test delimiters to correlate + # logs with the test that generated them. + + if args.logging_path: + stem.util.log.notice('Beginning test %s' % test_class) + start_time = time.time()
# Test classes look like... @@ -449,6 +466,9 @@ def _run_test(args, test_class, output_filters): println(' failed (%0.2fs)' % (time.time() - start_time), ERROR) println(test.output.apply_filters(test_results.getvalue(), *output_filters), NO_NL)
+ if args.logging_path: + stem.util.log.notice('Finished test %s' % test_class) + return run_result
diff --git a/stem/descriptor/remote.py b/stem/descriptor/remote.py index b2f066a3..7f1f44fa 100644 --- a/stem/descriptor/remote.py +++ b/stem/descriptor/remote.py @@ -596,7 +596,7 @@ class Query(object): raise ValueError("BUG: endpoints can only be ORPorts or DirPorts, '%s' was a %s" % (endpoint, type(endpoint).__name__))
self.runtime = time.time() - self.start_time - log.trace("Descriptors retrieved from %s in %0.2fs" % (downloaded_from, self.runtime)) + log.trace('Descriptors retrieved from %s in %0.2fs' % (downloaded_from, self.runtime)) except: exc = sys.exc_info()[1]
diff --git a/stem/util/log.py b/stem/util/log.py index beaf8580..92e76258 100644 --- a/stem/util/log.py +++ b/stem/util/log.py @@ -78,6 +78,11 @@ logging.addLevelName(LOG_VALUES[NOTICE], 'NOTICE') LOGGER = logging.getLogger('stem') LOGGER.setLevel(LOG_VALUES[TRACE])
+FORMATTER = logging.Formatter( + fmt = '%(asctime)s [%(levelname)s] %(message)s', + datefmt = '%m/%d/%Y %H:%M:%S', +) + # There's some messages that we don't want to log more than once. This set has # the messages IDs that we've logged which fall into this category. DEDUPLICATION_MESSAGE_IDS = set() @@ -221,6 +226,9 @@ class LogBuffer(logging.Handler):
.. versionchanged:: 1.4.0 Added the yield_records argument. + + .. deprecated:: 1.8.0 + This will be dropped in Stem 2.x. Use python's logging.BufferingHandler instead. """
def __init__(self, runlevel, yield_records = False): @@ -232,10 +240,7 @@ class LogBuffer(logging.Handler):
logging.Handler.__init__(self, level = logging_level(runlevel))
- self.formatter = logging.Formatter( - fmt = '%(asctime)s [%(levelname)s] %(message)s', - datefmt = '%m/%d/%Y %H:%M:%S') - + self.formatter = FORMATTER self._buffer = [] self._yield_records = yield_records
diff --git a/test/arguments.py b/test/arguments.py index 1ddf9240..0fa492d8 100644 --- a/test/arguments.py +++ b/test/arguments.py @@ -28,6 +28,7 @@ DEFAULT_ARGS = { 'run_integ': False, 'specific_test': [], 'logging_runlevel': None, + 'logging_path': None, 'tor_path': 'tor', 'run_targets': [test.Target.RUN_OPEN], 'attribute_targets': [], @@ -37,7 +38,7 @@ DEFAULT_ARGS = { }
OPT = 'auit:l:qvh' -OPT_EXPANDED = ['all', 'unit', 'integ', 'targets=', 'test=', 'log=', 'tor=', 'quiet', 'verbose', 'help'] +OPT_EXPANDED = ['all', 'unit', 'integ', 'targets=', 'test=', 'log=', 'log-file=', 'tor=', 'quiet', 'verbose', 'help']
def parse(argv): @@ -111,6 +112,8 @@ def parse(argv): raise ValueError(LOG_TYPE_ERROR % arg)
args['logging_runlevel'] = arg + elif opt == '--log-file': + args['logging_path'] = arg elif opt in ('--tor'): args['tor_path'] = arg elif opt in ('-q', '--quiet'): diff --git a/test/output.py b/test/output.py index 9df1bc93..92a47ac3 100644 --- a/test/output.py +++ b/test/output.py @@ -84,7 +84,7 @@ def print_divider(msg, is_header = False):
def print_logging(logging_buffer): - if SUPPRESS_STDOUT: + if SUPPRESS_STDOUT or logging_buffer is None: return
if not logging_buffer.is_empty(): diff --git a/test/settings.cfg b/test/settings.cfg index 944428e2..5b4feb60 100644 --- a/test/settings.cfg +++ b/test/settings.cfg @@ -40,8 +40,10 @@ msg.help | | -t, --target TARGET comma separated list of integ targets (see below) | --tor PATH custom tor binary to run testing against +| | -l, --log RUNLEVEL include log output with test results, runlevels are: | TRACE, DEBUG, INFO, NOTICE, WARN, ERROR +| --log-file PATH logs to this file, otherwise logging is to stdout | | -q, --quiet only present failures | -v, --verbose provides additional test output