From bba1c54edd73406e66ddae5ae2ac90183c3582bf Mon Sep 17 00:00:00 2001 From: John Newbery Date: Wed, 29 Nov 2017 13:21:51 -0500 Subject: [PATCH 1/3] [tests] Improve logging shutdown and add hint for combine_logs --- test/functional/test_framework/test_framework.py | 10 ++++++---- 1 file changed, 6 insertions(+), 4 deletions(-) diff --git a/test/functional/test_framework/test_framework.py b/test/functional/test_framework/test_framework.py index 4590b4c650..102babb9f4 100755 --- a/test/functional/test_framework/test_framework.py +++ b/test/functional/test_framework/test_framework.py @@ -167,14 +167,16 @@ class BitcoinTestFramework(): if success == TestStatus.PASSED: self.log.info("Tests successful") - sys.exit(TEST_EXIT_PASSED) + exit_code = TEST_EXIT_PASSED elif success == TestStatus.SKIPPED: self.log.info("Test skipped") - sys.exit(TEST_EXIT_SKIPPED) + exit_code = TEST_EXIT_SKIPPED else: self.log.error("Test failed. Test logging available at %s/test_framework.log", self.options.tmpdir) - logging.shutdown() - sys.exit(TEST_EXIT_FAILED) + self.log.error("Hint: Call {} '{}' to consolidate all logs".format(os.path.normpath(os.path.dirname(os.path.realpath(__file__)) + "/../combine_logs.py"), self.options.tmpdir)) + exit_code = TEST_EXIT_FAILED + logging.shutdown() + sys.exit(exit_code) # Methods to override in subclass test scripts. def set_test_params(self): From dba94ead0cb4ca90aeb894aca0a87a34e4dc9886 Mon Sep 17 00:00:00 2001 From: John Newbery Date: Wed, 29 Nov 2017 13:25:23 -0500 Subject: [PATCH 2/3] [tests] [travis-ci] Move Travis functional test log post processing to test_runner --- .../test_framework/test_framework.py | 16 -------------- test/functional/test_runner.py | 21 ++++++++++++++----- 2 files changed, 16 insertions(+), 21 deletions(-) diff --git a/test/functional/test_framework/test_framework.py b/test/functional/test_framework/test_framework.py index 102babb9f4..54fe689686 100755 --- a/test/functional/test_framework/test_framework.py +++ b/test/functional/test_framework/test_framework.py @@ -4,7 +4,6 @@ # file COPYING or http://www.opensource.org/licenses/mit-license.php. """Base class for RPC testing.""" -from collections import deque from enum import Enum import logging import optparse @@ -149,21 +148,6 @@ class BitcoinTestFramework(): shutil.rmtree(self.options.tmpdir) else: self.log.warning("Not cleaning up dir %s" % self.options.tmpdir) - if os.getenv("PYTHON_DEBUG", ""): - # Dump the end of the debug logs, to aid in debugging rare - # travis failures. - import glob - filenames = [self.options.tmpdir + "/test_framework.log"] - filenames += glob.glob(self.options.tmpdir + "/node*/regtest/debug.log") - MAX_LINES_TO_PRINT = 1000 - for fn in filenames: - try: - with open(fn, 'r') as f: - print("From", fn, ":") - print("".join(deque(f, MAX_LINES_TO_PRINT))) - except OSError: - print("Opening file %s failed." % fn) - traceback.print_exc() if success == TestStatus.PASSED: self.log.info("Tests successful") diff --git a/test/functional/test_runner.py b/test/functional/test_runner.py index d953e1585c..4407d3bf69 100755 --- a/test/functional/test_runner.py +++ b/test/functional/test_runner.py @@ -15,6 +15,7 @@ For a description of arguments recognized by test scripts, see """ import argparse +from collections import deque import configparser import datetime import os @@ -314,7 +315,7 @@ def run_tests(test_list, src_dir, build_dir, exeext, tmpdir, jobs=1, enable_cove max_len_name = len(max(test_list, key=len)) for _ in range(len(test_list)): - test_result, stdout, stderr = job_queue.get_next() + test_result, testdir, stdout, stderr = job_queue.get_next() test_results.append(test_result) if test_result.status == "Passed": @@ -325,6 +326,14 @@ def run_tests(test_list, src_dir, build_dir, exeext, tmpdir, jobs=1, enable_cove print("\n%s%s%s failed, Duration: %s s\n" % (BOLD[1], test_result.name, BOLD[0], test_result.time)) print(BOLD[1] + 'stdout:\n' + BOLD[0] + stdout + '\n') print(BOLD[1] + 'stderr:\n' + BOLD[0] + stderr + '\n') + if os.getenv("PYTHON_DEBUG", "") and os.path.isdir(testdir): + # Print the logs on travis, so they are preserved when the vm is disposed + print('{}Combine the logs and print the last {} lines ...{}'.format(BOLD[1], 4000, BOLD[0])) + print('\n============') + print('{}Combined log for {}:{}'.format(BOLD[1], testdir, BOLD[0])) + print('============\n') + combined_logs, _ = subprocess.Popen([os.path.join(tests_dir, 'combine_logs.py'), '-c', testdir], universal_newlines=True, stdout=subprocess.PIPE).communicate() + print("\n".join(deque(combined_logs.splitlines(), 4000))) print_results(test_results, max_len_name, (int(time.time() - time0))) @@ -389,13 +398,15 @@ class TestHandler: log_stdout = tempfile.SpooledTemporaryFile(max_size=2**16) log_stderr = tempfile.SpooledTemporaryFile(max_size=2**16) test_argv = t.split() - tmpdir = ["--tmpdir=%s/%s_%s" % (self.tmpdir, re.sub(".py$", "", test_argv[0]), portseed)] + testdir = "{}/{}_{}".format(self.tmpdir, re.sub(".py$", "", test_argv[0]), portseed) + tmpdir_arg = ["--tmpdir={}".format(testdir)] self.jobs.append((t, time.time(), - subprocess.Popen([self.tests_dir + test_argv[0]] + test_argv[1:] + self.flags + portseed_arg + tmpdir, + subprocess.Popen([self.tests_dir + test_argv[0]] + test_argv[1:] + self.flags + portseed_arg + tmpdir_arg, universal_newlines=True, stdout=log_stdout, stderr=log_stderr), + testdir, log_stdout, log_stderr)) if not self.jobs: @@ -404,7 +415,7 @@ class TestHandler: # Return first proc that finishes time.sleep(.5) for j in self.jobs: - (name, time0, proc, log_out, log_err) = j + (name, time0, proc, testdir, log_out, log_err) = j if os.getenv('TRAVIS') == 'true' and int(time.time() - time0) > 20 * 60: # In travis, timeout individual tests after 20 minutes (to stop tests hanging and not # providing useful output. @@ -422,7 +433,7 @@ class TestHandler: self.num_running -= 1 self.jobs.remove(j) - return TestResult(name, status, int(time.time() - time0)), stdout, stderr + return TestResult(name, status, int(time.time() - time0)), testdir, stdout, stderr print('.', end='', flush=True) class TestResult(): From ff8a9b068ae15c569ce66abb58bf6f909b879a7d Mon Sep 17 00:00:00 2001 From: John Newbery Date: Wed, 29 Nov 2017 13:28:45 -0500 Subject: [PATCH 3/3] [tests] Add combinedlogslen argument to test_runner.py Instead of calling combine_logs from test_runner when the environment variable PYTHON_DEBUG is set, add a combinedlogslen argument. This makes it easier to call when running locally, and allows a different length of combined logs to be printed. --- .travis.yml | 3 +-- test/functional/test_runner.py | 13 +++++++------ 2 files changed, 8 insertions(+), 8 deletions(-) diff --git a/.travis.yml b/.travis.yml index a643d2ff5d..d3dd37e76c 100644 --- a/.travis.yml +++ b/.travis.yml @@ -18,7 +18,6 @@ env: - CCACHE_COMPRESS=1 - BASE_OUTDIR=$TRAVIS_BUILD_DIR/out - SDK_URL=https://bitcoincore.org/depends-sources/sdks - - PYTHON_DEBUG=1 - WINEDEBUG=fixme-all matrix: # ARM @@ -79,7 +78,7 @@ script: - export LD_LIBRARY_PATH=$TRAVIS_BUILD_DIR/depends/$HOST/lib - if [ "$RUN_TESTS" = "true" ]; then travis_wait 30 make $MAKEJOBS check VERBOSE=1; fi - if [ "$TRAVIS_EVENT_TYPE" = "cron" ]; then extended="--extended --exclude pruning,dbcrash"; fi - - if [ "$RUN_TESTS" = "true" ]; then test/functional/test_runner.py --coverage --quiet ${extended}; fi + - if [ "$RUN_TESTS" = "true" ]; then test/functional/test_runner.py --combinedlogslen=4000 --coverage --quiet ${extended}; fi after_script: - echo $TRAVIS_COMMIT_RANGE - echo $TRAVIS_COMMIT_LOG diff --git a/test/functional/test_runner.py b/test/functional/test_runner.py index 4407d3bf69..8c5654a85d 100755 --- a/test/functional/test_runner.py +++ b/test/functional/test_runner.py @@ -175,6 +175,7 @@ def main(): epilog=''' Help text and arguments for individual test script:''', formatter_class=argparse.RawTextHelpFormatter) + parser.add_argument('--combinedlogslen', '-c', type=int, default=0, help='print a combined log (of length n lines) from all test nodes and test framework to the console on failure.') parser.add_argument('--coverage', action='store_true', help='generate a basic coverage report for the RPC interface') parser.add_argument('--exclude', '-x', help='specify a comma-separated-list of scripts to exclude.') parser.add_argument('--extended', action='store_true', help='run the extended test suite in addition to the basic tests') @@ -267,9 +268,9 @@ def main(): if not args.keepcache: shutil.rmtree("%s/test/cache" % config["environment"]["BUILDDIR"], ignore_errors=True) - run_tests(test_list, config["environment"]["SRCDIR"], config["environment"]["BUILDDIR"], config["environment"]["EXEEXT"], tmpdir, args.jobs, args.coverage, passon_args) + run_tests(test_list, config["environment"]["SRCDIR"], config["environment"]["BUILDDIR"], config["environment"]["EXEEXT"], tmpdir, args.jobs, args.coverage, passon_args, args.combinedlogslen) -def run_tests(test_list, src_dir, build_dir, exeext, tmpdir, jobs=1, enable_coverage=False, args=[]): +def run_tests(test_list, src_dir, build_dir, exeext, tmpdir, jobs=1, enable_coverage=False, args=[], combined_logs_len=0): # Warn if bitcoind is already running (unix only) try: if subprocess.check_output(["pidof", "bitcoind"]) is not None: @@ -326,14 +327,14 @@ def run_tests(test_list, src_dir, build_dir, exeext, tmpdir, jobs=1, enable_cove print("\n%s%s%s failed, Duration: %s s\n" % (BOLD[1], test_result.name, BOLD[0], test_result.time)) print(BOLD[1] + 'stdout:\n' + BOLD[0] + stdout + '\n') print(BOLD[1] + 'stderr:\n' + BOLD[0] + stderr + '\n') - if os.getenv("PYTHON_DEBUG", "") and os.path.isdir(testdir): - # Print the logs on travis, so they are preserved when the vm is disposed - print('{}Combine the logs and print the last {} lines ...{}'.format(BOLD[1], 4000, BOLD[0])) + if combined_logs_len and os.path.isdir(testdir): + # Print the final `combinedlogslen` lines of the combined logs + print('{}Combine the logs and print the last {} lines ...{}'.format(BOLD[1], combined_logs_len, BOLD[0])) print('\n============') print('{}Combined log for {}:{}'.format(BOLD[1], testdir, BOLD[0])) print('============\n') combined_logs, _ = subprocess.Popen([os.path.join(tests_dir, 'combine_logs.py'), '-c', testdir], universal_newlines=True, stdout=subprocess.PIPE).communicate() - print("\n".join(deque(combined_logs.splitlines(), 4000))) + print("\n".join(deque(combined_logs.splitlines(), combined_logs_len))) print_results(test_results, max_len_name, (int(time.time() - time0)))