test/functional/test_runner.py

   1 #!/usr/bin/env python3
   2 # Copyright (c) 2014-2016 The Bitcoin Core developers
   3 # Distributed under the MIT software license, see the accompanying
   4 # file COPYING or http://www.opensource.org/licenses/mit-license.php.
   5 """Run regression test suite.
   6
   7 This module calls down into individual test cases via subprocess. It will
   8 forward all unrecognized arguments onto the individual test scripts.
   9
  10 Functional tests are disabled on Windows by default. Use --force to run them anyway.
  11
  12 For a description of arguments recognized by test scripts, see
  13 `test/functional/test_framework/test_framework.py:BitcoinTestFramework.main`.
  14
  15 """
  16
  17 import argparse
  18 from collections import deque
  19 import configparser
  20 import datetime
  21 import os
  22 import time
  23 import shutil
  24 import signal
  25 import sys
  26 import subprocess
  27 import tempfile
  28 import re
  29 import logging
  30
  31 # Formatting. Default colors to empty strings.
  32 BOLD, BLUE, RED, GREY = ("", ""), ("", ""), ("", ""), ("", "")
  33 try:
  34     # Make sure python thinks it can write unicode to its stdout
  35     "\u2713".encode("utf_8").decode(sys.stdout.encoding)
  36     TICK = "✓ "
  37     CROSS = "✖ "
  38     CIRCLE = "○ "
  39 except UnicodeDecodeError:
  40     TICK = "P "
  41     CROSS = "x "
  42     CIRCLE = "o "
  43
  44 if os.name == 'posix':
  45     # primitive formatting on supported
  46     # terminal via ANSI escape sequences:
  47     BOLD = ('\033[0m', '\033[1m')
  48     BLUE = ('\033[0m', '\033[0;34m')
  49     RED = ('\033[0m', '\033[0;31m')
  50     GREY = ('\033[0m', '\033[1;30m')
  51
  52 TEST_EXIT_PASSED = 0
  53 TEST_EXIT_SKIPPED = 77
  54
  55 BASE_SCRIPTS= [
  56     # Scripts that are run by the travis build process.
  57     # Longest test should go first, to favor running tests in parallel
  58     'wallet-hd.py',
  59     'walletbackup.py',
  60     # vv Tests less than 5m vv
  61     'p2p-fullblocktest.py',
  62     'fundrawtransaction.py',
  63     'p2p-compactblocks.py',
  64     'segwit.py',
  65     # vv Tests less than 2m vv
  66     'wallet.py',
  67     'wallet-accounts.py',
  68     'p2p-segwit.py',
  69     'wallet-dump.py',
  70     'listtransactions.py',
  71     # vv Tests less than 60s vv
  72     'sendheaders.py',
  73     'zapwallettxes.py',
  74     'importmulti.py',
  75     'mempool_limit.py',
  76     'merkle_blocks.py',
  77     'receivedby.py',
  78     'abandonconflict.py',
  79     'bip68-112-113-p2p.py',
  80     'rawtransactions.py',
  81     'reindex.py',
  82     # vv Tests less than 30s vv
  83     'keypool-topup.py',
  84     'zmq_test.py',
  85     'bitcoin_cli.py',
  86     'mempool_resurrect_test.py',
  87     'txn_doublespend.py --mineblock',
  88     'txn_clone.py',
  89     'getchaintips.py',
  90     'rest.py',
  91     'mempool_spendcoinbase.py',
  92     'mempool_reorg.py',
  93     'mempool_persist.py',
  94     'multiwallet.py',
  95     'httpbasics.py',
  96     'multi_rpc.py',
  97     'proxy_test.py',
  98     'signrawtransactions.py',
  99     'disconnect_ban.py',
 100     'decodescript.py',
 101     'blockchain.py',
 102     'deprecated_rpc.py',
 103     'disablewallet.py',
 104     'net.py',
 105     'keypool.py',
 106     'p2p-mempool.py',
 107     'prioritise_transaction.py',
 108     'invalidblockrequest.py',
 109     'invalidtxrequest.py',
 110     'p2p-versionbits-warning.py',
 111     'preciousblock.py',
 112     'importprunedfunds.py',
 113     'signmessages.py',
 114     'nulldummy.py',
 115     'import-rescan.py',
 116     'mining.py',
 117     'bumpfee.py',
 118     'rpcnamedargs.py',
 119     'listsinceblock.py',
 120     'p2p-leaktests.py',
 121     'wallet-encryption.py',
 122     'bipdersig-p2p.py',
 123     'bip65-cltv-p2p.py',
 124     'uptime.py',
 125     'resendwallettransactions.py',
 126     'minchainwork.py',
 127     'p2p-fingerprint.py',
 128     'uacomment.py',
 129     'p2p-acceptblock.py',
 130     'feature_logging.py',
 131     'node_network_limited.py',
 132     'conf_args.py',
 133 ]
 134
 135 EXTENDED_SCRIPTS = [
 136     # These tests are not run by the travis build process.
 137     # Longest test should go first, to favor running tests in parallel
 138     'pruning.py',
 139     # vv Tests less than 20m vv
 140     'smartfees.py',
 141     # vv Tests less than 5m vv
 142     'maxuploadtarget.py',
 143     'mempool_packages.py',
 144     'dbcrash.py',
 145     # vv Tests less than 2m vv
 146     'bip68-sequence.py',
 147     'getblocktemplate_longpoll.py',
 148     'p2p-timeouts.py',
 149     # vv Tests less than 60s vv
 150     'bip9-softforks.py',
 151     'p2p-feefilter.py',
 152     'rpcbind_test.py',
 153     # vv Tests less than 30s vv
 154     'assumevalid.py',
 155     'example_test.py',
 156     'txn_doublespend.py',
 157     'txn_clone.py --mineblock',
 158     'notifications.py',
 159     'invalidateblock.py',
 160     'replace-by-fee.py',
 161 ]
 162
 163 # Place EXTENDED_SCRIPTS first since it has the 3 longest running tests
 164 ALL_SCRIPTS = EXTENDED_SCRIPTS + BASE_SCRIPTS
 165
 166 NON_SCRIPTS = [
 167     # These are python files that live in the functional tests directory, but are not test scripts.
 168     "combine_logs.py",
 169     "create_cache.py",
 170     "test_runner.py",
 171 ]
 172
 173 def main():
 174     # Parse arguments and pass through unrecognised args
 175     parser = argparse.ArgumentParser(add_help=False,
 176                                      usage='%(prog)s [test_runner.py options] [script options] [scripts]',
 177                                      description=__doc__,
 178                                      epilog='''
 179     Help text and arguments for individual test script:''',
 180                                      formatter_class=argparse.RawTextHelpFormatter)
 181     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.')
 182     parser.add_argument('--coverage', action='store_true', help='generate a basic coverage report for the RPC interface')
 183     parser.add_argument('--exclude', '-x', help='specify a comma-separated-list of scripts to exclude.')
 184     parser.add_argument('--extended', action='store_true', help='run the extended test suite in addition to the basic tests')
 185     parser.add_argument('--force', '-f', action='store_true', help='run tests even on platforms where they are disabled by default (e.g. windows).')
 186     parser.add_argument('--help', '-h', '-?', action='store_true', help='print help text and exit')
 187     parser.add_argument('--jobs', '-j', type=int, default=4, help='how many test scripts to run in parallel. Default=4.')
 188     parser.add_argument('--keepcache', '-k', action='store_true', help='the default behavior is to flush the cache directory on startup. --keepcache retains the cache from the previous testrun.')
 189     parser.add_argument('--quiet', '-q', action='store_true', help='only print results summary and failure logs')
 190     parser.add_argument('--tmpdirprefix', '-t', default=tempfile.gettempdir(), help="Root directory for datadirs")
 191     args, unknown_args = parser.parse_known_args()
 192
 193     # args to be passed on always start with two dashes; tests are the remaining unknown args
 194     tests = [arg for arg in unknown_args if arg[:2] != "--"]
 195     passon_args = [arg for arg in unknown_args if arg[:2] == "--"]
 196
 197     # Read config generated by configure.
 198     config = configparser.ConfigParser()
 199     configfile = os.path.abspath(os.path.dirname(__file__)) + "/../config.ini"
 200     config.read_file(open(configfile))
 201
 202     passon_args.append("--configfile=%s" % configfile)
 203
 204     # Set up logging
 205     logging_level = logging.INFO if args.quiet else logging.DEBUG
 206     logging.basicConfig(format='%(message)s', level=logging_level)
 207
 208     # Create base test directory
 209     tmpdir = "%s/bitcoin_test_runner_%s" % (args.tmpdirprefix, datetime.datetime.now().strftime("%Y%m%d_%H%M%S"))
 210     os.makedirs(tmpdir)
 211
 212     logging.debug("Temporary test directory at %s" % tmpdir)
 213
 214     enable_wallet = config["components"].getboolean("ENABLE_WALLET")
 215     enable_utils = config["components"].getboolean("ENABLE_UTILS")
 216     enable_bitcoind = config["components"].getboolean("ENABLE_BITCOIND")
 217
 218     if config["environment"]["EXEEXT"] == ".exe" and not args.force:
 219         # https://github.com/bitcoin/bitcoin/commit/d52802551752140cf41f0d9a225a43e84404d3e9
 220         # https://github.com/bitcoin/bitcoin/pull/5677#issuecomment-136646964
 221         print("Tests currently disabled on Windows by default. Use --force option to enable")
 222         sys.exit(0)
 223
 224     if not (enable_wallet and enable_utils and enable_bitcoind):
 225         print("No functional tests to run. Wallet, utils, and bitcoind must all be enabled")
 226         print("Rerun `configure` with -enable-wallet, -with-utils and -with-daemon and rerun make")
 227         sys.exit(0)
 228
 229     # Build list of tests
 230     if tests:
 231         # Individual tests have been specified. Run specified tests that exist
 232         # in the ALL_SCRIPTS list. Accept the name with or without .py extension.
 233         tests = [re.sub("\.py$", "", t) + ".py" for t in tests]
 234         test_list = []
 235         for t in tests:
 236             if t in ALL_SCRIPTS:
 237                 test_list.append(t)
 238             else:
 239                 print("{}WARNING!{} Test '{}' not found in full test list.".format(BOLD[1], BOLD[0], t))
 240     else:
 241         # No individual tests have been specified.
 242         # Run all base tests, and optionally run extended tests.
 243         test_list = BASE_SCRIPTS
 244         if args.extended:
 245             # place the EXTENDED_SCRIPTS first since the three longest ones
 246             # are there and the list is shorter
 247             test_list = EXTENDED_SCRIPTS + test_list
 248
 249     # Remove the test cases that the user has explicitly asked to exclude.
 250     if args.exclude:
 251         tests_excl = [re.sub("\.py$", "", t) + ".py" for t in args.exclude.split(',')]
 252         for exclude_test in tests_excl:
 253             if exclude_test in test_list:
 254                 test_list.remove(exclude_test)
 255             else:
 256                 print("{}WARNING!{} Test '{}' not found in current test list.".format(BOLD[1], BOLD[0], exclude_test))
 257
 258     if not test_list:
 259         print("No valid test scripts specified. Check that your test is in one "
 260               "of the test lists in test_runner.py, or run test_runner.py with no arguments to run all tests")
 261         sys.exit(0)
 262
 263     if args.help:
 264         # Print help for test_runner.py, then print help of the first script (with args removed) and exit.
 265         parser.print_help()
 266         subprocess.check_call([(config["environment"]["SRCDIR"] + '/test/functional/' + test_list[0].split()[0])] + ['-h'])
 267         sys.exit(0)
 268
 269     check_script_list(config["environment"]["SRCDIR"])
 270
 271     if not args.keepcache:
 272         shutil.rmtree("%s/test/cache" % config["environment"]["BUILDDIR"], ignore_errors=True)
 273
 274     run_tests(test_list, config["environment"]["SRCDIR"], config["environment"]["BUILDDIR"], config["environment"]["EXEEXT"], tmpdir, args.jobs, args.coverage, passon_args, args.combinedlogslen)
 275
 276 def run_tests(test_list, src_dir, build_dir, exeext, tmpdir, jobs=1, enable_coverage=False, args=[], combined_logs_len=0):
 277     # Warn if bitcoind is already running (unix only)
 278     try:
 279         if subprocess.check_output(["pidof", "bitcoind"]) is not None:
 280             print("%sWARNING!%s There is already a bitcoind process running on this system. Tests may fail unexpectedly due to resource contention!" % (BOLD[1], BOLD[0]))
 281     except (OSError, subprocess.SubprocessError):
 282         pass
 283
 284     # Warn if there is a cache directory
 285     cache_dir = "%s/test/cache" % build_dir
 286     if os.path.isdir(cache_dir):
 287         print("%sWARNING!%s There is a cache directory here: %s. If tests fail unexpectedly, try deleting the cache directory." % (BOLD[1], BOLD[0], cache_dir))
 288
 289     #Set env vars
 290     if "BITCOIND" not in os.environ:
 291         os.environ["BITCOIND"] = build_dir + '/src/bitcoind' + exeext
 292         os.environ["BITCOINCLI"] = build_dir + '/src/bitcoin-cli' + exeext
 293
 294     tests_dir = src_dir + '/test/functional/'
 295
 296     flags = ["--srcdir={}/src".format(build_dir)] + args
 297     flags.append("--cachedir=%s" % cache_dir)
 298
 299     if enable_coverage:
 300         coverage = RPCCoverage()
 301         flags.append(coverage.flag)
 302         logging.debug("Initializing coverage directory at %s" % coverage.dir)
 303     else:
 304         coverage = None
 305
 306     if len(test_list) > 1 and jobs > 1:
 307         # Populate cache
 308         try:
 309             subprocess.check_output([tests_dir + 'create_cache.py'] + flags + ["--tmpdir=%s/cache" % tmpdir])
 310         except Exception as e:
 311             print(e.output)
 312             raise e
 313
 314     #Run Tests
 315     job_queue = TestHandler(jobs, tests_dir, tmpdir, test_list, flags)
 316     time0 = time.time()
 317     test_results = []
 318
 319     max_len_name = len(max(test_list, key=len))
 320
 321     for _ in range(len(test_list)):
 322         test_result, testdir, stdout, stderr = job_queue.get_next()
 323         test_results.append(test_result)
 324
 325         if test_result.status == "Passed":
 326             logging.debug("\n%s%s%s passed, Duration: %s s" % (BOLD[1], test_result.name, BOLD[0], test_result.time))
 327         elif test_result.status == "Skipped":
 328             logging.debug("\n%s%s%s skipped" % (BOLD[1], test_result.name, BOLD[0]))
 329         else:
 330             print("\n%s%s%s failed, Duration: %s s\n" % (BOLD[1], test_result.name, BOLD[0], test_result.time))
 331             print(BOLD[1] + 'stdout:\n' + BOLD[0] + stdout + '\n')
 332             print(BOLD[1] + 'stderr:\n' + BOLD[0] + stderr + '\n')
 333             if combined_logs_len and os.path.isdir(testdir):
 334                 # Print the final `combinedlogslen` lines of the combined logs
 335                 print('{}Combine the logs and print the last {} lines ...{}'.format(BOLD[1], combined_logs_len, BOLD[0]))
 336                 print('\n============')
 337                 print('{}Combined log for {}:{}'.format(BOLD[1], testdir, BOLD[0]))
 338                 print('============\n')
 339                 combined_logs, _ = subprocess.Popen([os.path.join(tests_dir, 'combine_logs.py'), '-c', testdir], universal_newlines=True, stdout=subprocess.PIPE).communicate()
 340                 print("\n".join(deque(combined_logs.splitlines(), combined_logs_len)))
 341
 342     print_results(test_results, max_len_name, (int(time.time() - time0)))
 343
 344     if coverage:
 345         coverage.report_rpc_coverage()
 346
 347         logging.debug("Cleaning up coverage data")
 348         coverage.cleanup()
 349
 350     # Clear up the temp directory if all subdirectories are gone
 351     if not os.listdir(tmpdir):
 352         os.rmdir(tmpdir)
 353
 354     all_passed = all(map(lambda test_result: test_result.was_successful, test_results))
 355
 356     sys.exit(not all_passed)
 357
 358 def print_results(test_results, max_len_name, runtime):
 359     results = "\n" + BOLD[1] + "%s | %s | %s\n\n" % ("TEST".ljust(max_len_name), "STATUS   ", "DURATION") + BOLD[0]
 360
 361     test_results.sort(key=lambda result: result.name.lower())
 362     all_passed = True
 363     time_sum = 0
 364
 365     for test_result in test_results:
 366         all_passed = all_passed and test_result.was_successful
 367         time_sum += test_result.time
 368         test_result.padding = max_len_name
 369         results += str(test_result)
 370
 371     status = TICK + "Passed" if all_passed else CROSS + "Failed"
 372     results += BOLD[1] + "\n%s | %s | %s s (accumulated) \n" % ("ALL".ljust(max_len_name), status.ljust(9), time_sum) + BOLD[0]
 373     results += "Runtime: %s s\n" % (runtime)
 374     print(results)
 375
 376 class TestHandler:
 377     """
 378     Trigger the test scripts passed in via the list.
 379     """
 380
 381     def __init__(self, num_tests_parallel, tests_dir, tmpdir, test_list=None, flags=None):
 382         assert(num_tests_parallel >= 1)
 383         self.num_jobs = num_tests_parallel
 384         self.tests_dir = tests_dir
 385         self.tmpdir = tmpdir
 386         self.test_list = test_list
 387         self.flags = flags
 388         self.num_running = 0
 389         # In case there is a graveyard of zombie bitcoinds, we can apply a
 390         # pseudorandom offset to hopefully jump over them.
 391         # (625 is PORT_RANGE/MAX_NODES)
 392         self.portseed_offset = int(time.time() * 1000) % 625
 393         self.jobs = []
 394
 395     def get_next(self):
 396         while self.num_running < self.num_jobs and self.test_list:
 397             # Add tests
 398             self.num_running += 1
 399             t = self.test_list.pop(0)
 400             portseed = len(self.test_list) + self.portseed_offset
 401             portseed_arg = ["--portseed={}".format(portseed)]
 402             log_stdout = tempfile.SpooledTemporaryFile(max_size=2**16)
 403             log_stderr = tempfile.SpooledTemporaryFile(max_size=2**16)
 404             test_argv = t.split()
 405             testdir = "{}/{}_{}".format(self.tmpdir, re.sub(".py$", "", test_argv[0]), portseed)
 406             tmpdir_arg = ["--tmpdir={}".format(testdir)]
 407             self.jobs.append((t,
 408                               time.time(),
 409                               subprocess.Popen([self.tests_dir + test_argv[0]] + test_argv[1:] + self.flags + portseed_arg + tmpdir_arg,
 410                                                universal_newlines=True,
 411                                                stdout=log_stdout,
 412                                                stderr=log_stderr),
 413                               testdir,
 414                               log_stdout,
 415                               log_stderr))
 416         if not self.jobs:
 417             raise IndexError('pop from empty list')
 418         while True:
 419             # Return first proc that finishes
 420             time.sleep(.5)
 421             for j in self.jobs:
 422                 (name, time0, proc, testdir, log_out, log_err) = j
 423                 if os.getenv('TRAVIS') == 'true' and int(time.time() - time0) > 20 * 60:
 424                     # In travis, timeout individual tests after 20 minutes (to stop tests hanging and not
 425                     # providing useful output.
 426                     proc.send_signal(signal.SIGINT)
 427                 if proc.poll() is not None:
 428                     log_out.seek(0), log_err.seek(0)
 429                     [stdout, stderr] = [l.read().decode('utf-8') for l in (log_out, log_err)]
 430                     log_out.close(), log_err.close()
 431                     if proc.returncode == TEST_EXIT_PASSED and stderr == "":
 432                         status = "Passed"
 433                     elif proc.returncode == TEST_EXIT_SKIPPED:
 434                         status = "Skipped"
 435                     else:
 436                         status = "Failed"
 437                     self.num_running -= 1
 438                     self.jobs.remove(j)
 439
 440                     return TestResult(name, status, int(time.time() - time0)), testdir, stdout, stderr
 441             print('.', end='', flush=True)
 442
 443 class TestResult():
 444     def __init__(self, name, status, time):
 445         self.name = name
 446         self.status = status
 447         self.time = time
 448         self.padding = 0
 449
 450     def __repr__(self):
 451         if self.status == "Passed":
 452             color = BLUE
 453             glyph = TICK
 454         elif self.status == "Failed":
 455             color = RED
 456             glyph = CROSS
 457         elif self.status == "Skipped":
 458             color = GREY
 459             glyph = CIRCLE
 460
 461         return color[1] + "%s | %s%s | %s s\n" % (self.name.ljust(self.padding), glyph, self.status.ljust(7), self.time) + color[0]
 462
 463     @property
 464     def was_successful(self):
 465         return self.status != "Failed"
 466
 467
 468 def check_script_list(src_dir):
 469     """Check scripts directory.
 470
 471     Check that there are no scripts in the functional tests directory which are
 472     not being run by pull-tester.py."""
 473     script_dir = src_dir + '/test/functional/'
 474     python_files = set([t for t in os.listdir(script_dir) if t[-3:] == ".py"])
 475     missed_tests = list(python_files - set(map(lambda x: x.split()[0], ALL_SCRIPTS + NON_SCRIPTS)))
 476     if len(missed_tests) != 0:
 477         print("%sWARNING!%s The following scripts are not being run: %s. Check the test lists in test_runner.py." % (BOLD[1], BOLD[0], str(missed_tests)))
 478         if os.getenv('TRAVIS') == 'true':
 479             # On travis this warning is an error to prevent merging incomplete commits into master
 480             sys.exit(1)
 481
 482 class RPCCoverage():
 483     """
 484     Coverage reporting utilities for test_runner.
 485
 486     Coverage calculation works by having each test script subprocess write
 487     coverage files into a particular directory. These files contain the RPC
 488     commands invoked during testing, as well as a complete listing of RPC
 489     commands per `bitcoin-cli help` (`rpc_interface.txt`).
 490
 491     After all tests complete, the commands run are combined and diff'd against
 492     the complete list to calculate uncovered RPC commands.
 493
 494     See also: test/functional/test_framework/coverage.py
 495
 496     """
 497     def __init__(self):
 498         self.dir = tempfile.mkdtemp(prefix="coverage")
 499         self.flag = '--coveragedir=%s' % self.dir
 500
 501     def report_rpc_coverage(self):
 502         """
 503         Print out RPC commands that were unexercised by tests.
 504
 505         """
 506         uncovered = self._get_uncovered_rpc_commands()
 507
 508         if uncovered:
 509             print("Uncovered RPC commands:")
 510             print("".join(("  - %s\n" % i) for i in sorted(uncovered)))
 511         else:
 512             print("All RPC commands covered.")
 513
 514     def cleanup(self):
 515         return shutil.rmtree(self.dir)
 516
 517     def _get_uncovered_rpc_commands(self):
 518         """
 519         Return a set of currently untested RPC commands.
 520
 521         """
 522         # This is shared from `test/functional/test-framework/coverage.py`
 523         reference_filename = 'rpc_interface.txt'
 524         coverage_file_prefix = 'coverage.'
 525
 526         coverage_ref_filename = os.path.join(self.dir, reference_filename)
 527         coverage_filenames = set()
 528         all_cmds = set()
 529         covered_cmds = set()
 530
 531         if not os.path.isfile(coverage_ref_filename):
 532             raise RuntimeError("No coverage reference found")
 533
 534         with open(coverage_ref_filename, 'r') as f:
 535             all_cmds.update([i.strip() for i in f.readlines()])
 536
 537         for root, dirs, files in os.walk(self.dir):
 538             for filename in files:
 539                 if filename.startswith(coverage_file_prefix):
 540                     coverage_filenames.add(os.path.join(root, filename))
 541
 542         for filename in coverage_filenames:
 543             with open(filename, 'r') as f:
 544                 covered_cmds.update([i.strip() for i in f.readlines()])
 545
 546         return all_cmds - covered_cmds
 547
 548
 549 if __name__ == '__main__':
 550     main()