test/functional/test_framework/test_framework.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 """Base class for RPC testing."""
   6
   7 from collections import deque
   8 from enum import Enum
   9 import logging
  10 import optparse
  11 import os
  12 import pdb
  13 import shutil
  14 import sys
  15 import tempfile
  16 import time
  17 import traceback
  18
  19 from .authproxy import JSONRPCException
  20 from . import coverage
  21 from .test_node import TestNode
  22 from .util import (
  23     MAX_NODES,
  24     PortSeed,
  25     assert_equal,
  26     check_json_precision,
  27     connect_nodes_bi,
  28     disconnect_nodes,
  29     initialize_datadir,
  30     log_filename,
  31     p2p_port,
  32     set_node_times,
  33     sync_blocks,
  34     sync_mempools,
  35 )
  36
  37 class TestStatus(Enum):
  38     PASSED = 1
  39     FAILED = 2
  40     SKIPPED = 3
  41
  42 TEST_EXIT_PASSED = 0
  43 TEST_EXIT_FAILED = 1
  44 TEST_EXIT_SKIPPED = 77
  45
  46 class BitcoinTestFramework():
  47     """Base class for a bitcoin test script.
  48
  49     Individual bitcoin test scripts should subclass this class and override the set_test_params() and run_test() methods.
  50
  51     Individual tests can also override the following methods to customize the test setup:
  52
  53     - add_options()
  54     - setup_chain()
  55     - setup_network()
  56     - setup_nodes()
  57
  58     The __init__() and main() methods should not be overridden.
  59
  60     This class also contains various public and private helper methods."""
  61
  62     def __init__(self):
  63         """Sets test framework defaults. Do not override this method. Instead, override the set_test_params() method"""
  64         self.setup_clean_chain = False
  65         self.nodes = []
  66         self.mocktime = 0
  67         self.set_test_params()
  68
  69         assert hasattr(self, "num_nodes"), "Test must set self.num_nodes in set_test_params()"
  70
  71     def main(self):
  72         """Main function. This should not be overridden by the subclass test scripts."""
  73
  74         parser = optparse.OptionParser(usage="%prog [options]")
  75         parser.add_option("--nocleanup", dest="nocleanup", default=False, action="store_true",
  76                           help="Leave bitcoinds and test.* datadir on exit or error")
  77         parser.add_option("--noshutdown", dest="noshutdown", default=False, action="store_true",
  78                           help="Don't stop bitcoinds after the test execution")
  79         parser.add_option("--srcdir", dest="srcdir", default=os.path.normpath(os.path.dirname(os.path.realpath(__file__)) + "/../../../src"),
  80                           help="Source directory containing bitcoind/bitcoin-cli (default: %default)")
  81         parser.add_option("--cachedir", dest="cachedir", default=os.path.normpath(os.path.dirname(os.path.realpath(__file__)) + "/../../cache"),
  82                           help="Directory for caching pregenerated datadirs")
  83         parser.add_option("--tmpdir", dest="tmpdir", help="Root directory for datadirs")
  84         parser.add_option("-l", "--loglevel", dest="loglevel", default="INFO",
  85                           help="log events at this level and higher to the console. Can be set to DEBUG, INFO, WARNING, ERROR or CRITICAL. Passing --loglevel DEBUG will output all logs to console. Note that logs at all levels are always written to the test_framework.log file in the temporary test directory.")
  86         parser.add_option("--tracerpc", dest="trace_rpc", default=False, action="store_true",
  87                           help="Print out all RPC calls as they are made")
  88         parser.add_option("--portseed", dest="port_seed", default=os.getpid(), type='int',
  89                           help="The seed to use for assigning port numbers (default: current process id)")
  90         parser.add_option("--coveragedir", dest="coveragedir",
  91                           help="Write tested RPC commands into this directory")
  92         parser.add_option("--configfile", dest="configfile",
  93                           help="Location of the test framework config file")
  94         parser.add_option("--pdbonfailure", dest="pdbonfailure", default=False, action="store_true",
  95                           help="Attach a python debugger if test fails")
  96         self.add_options(parser)
  97         (self.options, self.args) = parser.parse_args()
  98
  99         PortSeed.n = self.options.port_seed
 100
 101         os.environ['PATH'] = self.options.srcdir + ":" + self.options.srcdir + "/qt:" + os.environ['PATH']
 102
 103         check_json_precision()
 104
 105         self.options.cachedir = os.path.abspath(self.options.cachedir)
 106
 107         # Set up temp directory and start logging
 108         if self.options.tmpdir:
 109             self.options.tmpdir = os.path.abspath(self.options.tmpdir)
 110             os.makedirs(self.options.tmpdir, exist_ok=False)
 111         else:
 112             self.options.tmpdir = tempfile.mkdtemp(prefix="test")
 113         self._start_logging()
 114
 115         success = TestStatus.FAILED
 116
 117         try:
 118             self.setup_chain()
 119             self.setup_network()
 120             self.run_test()
 121             success = TestStatus.PASSED
 122         except JSONRPCException as e:
 123             self.log.exception("JSONRPC error")
 124         except SkipTest as e:
 125             self.log.warning("Test Skipped: %s" % e.message)
 126             success = TestStatus.SKIPPED
 127         except AssertionError as e:
 128             self.log.exception("Assertion failed")
 129         except KeyError as e:
 130             self.log.exception("Key error")
 131         except Exception as e:
 132             self.log.exception("Unexpected exception caught during testing")
 133         except KeyboardInterrupt as e:
 134             self.log.warning("Exiting after keyboard interrupt")
 135
 136         if success == TestStatus.FAILED and self.options.pdbonfailure:
 137             print("Testcase failed. Attaching python debugger. Enter ? for help")
 138             pdb.set_trace()
 139
 140         if not self.options.noshutdown:
 141             self.log.info("Stopping nodes")
 142             if self.nodes:
 143                 self.stop_nodes()
 144         else:
 145             self.log.info("Note: bitcoinds were not stopped and may still be running")
 146
 147         if not self.options.nocleanup and not self.options.noshutdown and success != TestStatus.FAILED:
 148             self.log.info("Cleaning up")
 149             shutil.rmtree(self.options.tmpdir)
 150         else:
 151             self.log.warning("Not cleaning up dir %s" % self.options.tmpdir)
 152             if os.getenv("PYTHON_DEBUG", ""):
 153                 # Dump the end of the debug logs, to aid in debugging rare
 154                 # travis failures.
 155                 import glob
 156                 filenames = [self.options.tmpdir + "/test_framework.log"]
 157                 filenames += glob.glob(self.options.tmpdir + "/node*/regtest/debug.log")
 158                 MAX_LINES_TO_PRINT = 1000
 159                 for fn in filenames:
 160                     try:
 161                         with open(fn, 'r') as f:
 162                             print("From", fn, ":")
 163                             print("".join(deque(f, MAX_LINES_TO_PRINT)))
 164                     except OSError:
 165                         print("Opening file %s failed." % fn)
 166                         traceback.print_exc()
 167
 168         if success == TestStatus.PASSED:
 169             self.log.info("Tests successful")
 170             sys.exit(TEST_EXIT_PASSED)
 171         elif success == TestStatus.SKIPPED:
 172             self.log.info("Test skipped")
 173             sys.exit(TEST_EXIT_SKIPPED)
 174         else:
 175             self.log.error("Test failed. Test logging available at %s/test_framework.log", self.options.tmpdir)
 176             logging.shutdown()
 177             sys.exit(TEST_EXIT_FAILED)
 178
 179     # Methods to override in subclass test scripts.
 180     def set_test_params(self):
 181         """Tests must this method to change default values for number of nodes, topology, etc"""
 182         raise NotImplementedError
 183
 184     def add_options(self, parser):
 185         """Override this method to add command-line options to the test"""
 186         pass
 187
 188     def setup_chain(self):
 189         """Override this method to customize blockchain setup"""
 190         self.log.info("Initializing test directory " + self.options.tmpdir)
 191         if self.setup_clean_chain:
 192             self._initialize_chain_clean()
 193         else:
 194             self._initialize_chain()
 195
 196     def setup_network(self):
 197         """Override this method to customize test network topology"""
 198         self.setup_nodes()
 199
 200         # Connect the nodes as a "chain".  This allows us
 201         # to split the network between nodes 1 and 2 to get
 202         # two halves that can work on competing chains.
 203         for i in range(self.num_nodes - 1):
 204             connect_nodes_bi(self.nodes, i, i + 1)
 205         self.sync_all()
 206
 207     def setup_nodes(self):
 208         """Override this method to customize test node setup"""
 209         extra_args = None
 210         if hasattr(self, "extra_args"):
 211             extra_args = self.extra_args
 212         self.add_nodes(self.num_nodes, extra_args)
 213         self.start_nodes()
 214
 215     def run_test(self):
 216         """Tests must override this method to define test logic"""
 217         raise NotImplementedError
 218
 219     # Public helper methods. These can be accessed by the subclass test scripts.
 220
 221     def add_nodes(self, num_nodes, extra_args=None, rpchost=None, timewait=None, binary=None):
 222         """Instantiate TestNode objects"""
 223
 224         if extra_args is None:
 225             extra_args = [[]] * num_nodes
 226         if binary is None:
 227             binary = [None] * num_nodes
 228         assert_equal(len(extra_args), num_nodes)
 229         assert_equal(len(binary), num_nodes)
 230         for i in range(num_nodes):
 231             self.nodes.append(TestNode(i, self.options.tmpdir, extra_args[i], rpchost, timewait=timewait, binary=binary[i], stderr=None, mocktime=self.mocktime, coverage_dir=self.options.coveragedir))
 232
 233     def start_node(self, i, extra_args=None, stderr=None):
 234         """Start a bitcoind"""
 235
 236         node = self.nodes[i]
 237
 238         node.start(extra_args, stderr)
 239         node.wait_for_rpc_connection()
 240
 241         if self.options.coveragedir is not None:
 242             coverage.write_all_rpc_commands(self.options.coveragedir, node.rpc)
 243
 244     def start_nodes(self, extra_args=None):
 245         """Start multiple bitcoinds"""
 246
 247         if extra_args is None:
 248             extra_args = [None] * self.num_nodes
 249         assert_equal(len(extra_args), self.num_nodes)
 250         try:
 251             for i, node in enumerate(self.nodes):
 252                 node.start(extra_args[i])
 253             for node in self.nodes:
 254                 node.wait_for_rpc_connection()
 255         except:
 256             # If one node failed to start, stop the others
 257             self.stop_nodes()
 258             raise
 259
 260         if self.options.coveragedir is not None:
 261             for node in self.nodes:
 262                 coverage.write_all_rpc_commands(self.options.coveragedir, node.rpc)
 263
 264     def stop_node(self, i):
 265         """Stop a bitcoind test node"""
 266         self.nodes[i].stop_node()
 267         self.nodes[i].wait_until_stopped()
 268
 269     def stop_nodes(self):
 270         """Stop multiple bitcoind test nodes"""
 271         for node in self.nodes:
 272             # Issue RPC to stop nodes
 273             node.stop_node()
 274
 275         for node in self.nodes:
 276             # Wait for nodes to stop
 277             node.wait_until_stopped()
 278
 279     def restart_node(self, i, extra_args=None):
 280         """Stop and start a test node"""
 281         self.stop_node(i)
 282         self.start_node(i, extra_args)
 283
 284     def assert_start_raises_init_error(self, i, extra_args=None, expected_msg=None):
 285         with tempfile.SpooledTemporaryFile(max_size=2**16) as log_stderr:
 286             try:
 287                 self.start_node(i, extra_args, stderr=log_stderr)
 288                 self.stop_node(i)
 289             except Exception as e:
 290                 assert 'bitcoind exited' in str(e)  # node must have shutdown
 291                 self.nodes[i].running = False
 292                 self.nodes[i].process = None
 293                 if expected_msg is not None:
 294                     log_stderr.seek(0)
 295                     stderr = log_stderr.read().decode('utf-8')
 296                     if expected_msg not in stderr:
 297                         raise AssertionError("Expected error \"" + expected_msg + "\" not found in:\n" + stderr)
 298             else:
 299                 if expected_msg is None:
 300                     assert_msg = "bitcoind should have exited with an error"
 301                 else:
 302                     assert_msg = "bitcoind should have exited with expected error " + expected_msg
 303                 raise AssertionError(assert_msg)
 304
 305     def wait_for_node_exit(self, i, timeout):
 306         self.nodes[i].process.wait(timeout)
 307
 308     def split_network(self):
 309         """
 310         Split the network of four nodes into nodes 0/1 and 2/3.
 311         """
 312         disconnect_nodes(self.nodes[1], 2)
 313         disconnect_nodes(self.nodes[2], 1)
 314         self.sync_all([self.nodes[:2], self.nodes[2:]])
 315
 316     def join_network(self):
 317         """
 318         Join the (previously split) network halves together.
 319         """
 320         connect_nodes_bi(self.nodes, 1, 2)
 321         self.sync_all()
 322
 323     def sync_all(self, node_groups=None):
 324         if not node_groups:
 325             node_groups = [self.nodes]
 326
 327         for group in node_groups:
 328             sync_blocks(group)
 329             sync_mempools(group)
 330
 331     def enable_mocktime(self):
 332         """Enable mocktime for the script.
 333
 334         mocktime may be needed for scripts that use the cached version of the
 335         blockchain.  If the cached version of the blockchain is used without
 336         mocktime then the mempools will not sync due to IBD.
 337
 338         For backwared compatibility of the python scripts with previous
 339         versions of the cache, this helper function sets mocktime to Jan 1,
 340         2014 + (201 * 10 * 60)"""
 341         self.mocktime = 1388534400 + (201 * 10 * 60)
 342
 343     def disable_mocktime(self):
 344         self.mocktime = 0
 345
 346     # Private helper methods. These should not be accessed by the subclass test scripts.
 347
 348     def _start_logging(self):
 349         # Add logger and logging handlers
 350         self.log = logging.getLogger('TestFramework')
 351         self.log.setLevel(logging.DEBUG)
 352         # Create file handler to log all messages
 353         fh = logging.FileHandler(self.options.tmpdir + '/test_framework.log')
 354         fh.setLevel(logging.DEBUG)
 355         # Create console handler to log messages to stderr. By default this logs only error messages, but can be configured with --loglevel.
 356         ch = logging.StreamHandler(sys.stdout)
 357         # User can provide log level as a number or string (eg DEBUG). loglevel was caught as a string, so try to convert it to an int
 358         ll = int(self.options.loglevel) if self.options.loglevel.isdigit() else self.options.loglevel.upper()
 359         ch.setLevel(ll)
 360         # Format logs the same as bitcoind's debug.log with microprecision (so log files can be concatenated and sorted)
 361         formatter = logging.Formatter(fmt='%(asctime)s.%(msecs)03d000 %(name)s (%(levelname)s): %(message)s', datefmt='%Y-%m-%d %H:%M:%S')
 362         formatter.converter = time.gmtime
 363         fh.setFormatter(formatter)
 364         ch.setFormatter(formatter)
 365         # add the handlers to the logger
 366         self.log.addHandler(fh)
 367         self.log.addHandler(ch)
 368
 369         if self.options.trace_rpc:
 370             rpc_logger = logging.getLogger("BitcoinRPC")
 371             rpc_logger.setLevel(logging.DEBUG)
 372             rpc_handler = logging.StreamHandler(sys.stdout)
 373             rpc_handler.setLevel(logging.DEBUG)
 374             rpc_logger.addHandler(rpc_handler)
 375
 376     def _initialize_chain(self):
 377         """Initialize a pre-mined blockchain for use by the test.
 378
 379         Create a cache of a 200-block-long chain (with wallet) for MAX_NODES
 380         Afterward, create num_nodes copies from the cache."""
 381
 382         assert self.num_nodes <= MAX_NODES
 383         create_cache = False
 384         for i in range(MAX_NODES):
 385             if not os.path.isdir(os.path.join(self.options.cachedir, 'node' + str(i))):
 386                 create_cache = True
 387                 break
 388
 389         if create_cache:
 390             self.log.debug("Creating data directories from cached datadir")
 391
 392             # find and delete old cache directories if any exist
 393             for i in range(MAX_NODES):
 394                 if os.path.isdir(os.path.join(self.options.cachedir, "node" + str(i))):
 395                     shutil.rmtree(os.path.join(self.options.cachedir, "node" + str(i)))
 396
 397             # Create cache directories, run bitcoinds:
 398             for i in range(MAX_NODES):
 399                 datadir = initialize_datadir(self.options.cachedir, i)
 400                 args = [os.getenv("BITCOIND", "bitcoind"), "-server", "-keypool=1", "-datadir=" + datadir, "-discover=0"]
 401                 if i > 0:
 402                     args.append("-connect=127.0.0.1:" + str(p2p_port(0)))
 403                 self.nodes.append(TestNode(i, self.options.cachedir, extra_args=[], rpchost=None, timewait=None, binary=None, stderr=None, mocktime=self.mocktime, coverage_dir=None))
 404                 self.nodes[i].args = args
 405                 self.start_node(i)
 406
 407             # Wait for RPC connections to be ready
 408             for node in self.nodes:
 409                 node.wait_for_rpc_connection()
 410
 411             # Create a 200-block-long chain; each of the 4 first nodes
 412             # gets 25 mature blocks and 25 immature.
 413             # Note: To preserve compatibility with older versions of
 414             # initialize_chain, only 4 nodes will generate coins.
 415             #
 416             # blocks are created with timestamps 10 minutes apart
 417             # starting from 2010 minutes in the past
 418             self.enable_mocktime()
 419             block_time = self.mocktime - (201 * 10 * 60)
 420             for i in range(2):
 421                 for peer in range(4):
 422                     for j in range(25):
 423                         set_node_times(self.nodes, block_time)
 424                         self.nodes[peer].generate(1)
 425                         block_time += 10 * 60
 426                     # Must sync before next peer starts generating blocks
 427                     sync_blocks(self.nodes)
 428
 429             # Shut them down, and clean up cache directories:
 430             self.stop_nodes()
 431             self.nodes = []
 432             self.disable_mocktime()
 433             for i in range(MAX_NODES):
 434                 os.remove(log_filename(self.options.cachedir, i, "debug.log"))
 435                 os.remove(log_filename(self.options.cachedir, i, "wallets/db.log"))
 436                 os.remove(log_filename(self.options.cachedir, i, "peers.dat"))
 437                 os.remove(log_filename(self.options.cachedir, i, "fee_estimates.dat"))
 438
 439         for i in range(self.num_nodes):
 440             from_dir = os.path.join(self.options.cachedir, "node" + str(i))
 441             to_dir = os.path.join(self.options.tmpdir, "node" + str(i))
 442             shutil.copytree(from_dir, to_dir)
 443             initialize_datadir(self.options.tmpdir, i)  # Overwrite port/rpcport in bitcoin.conf
 444
 445     def _initialize_chain_clean(self):
 446         """Initialize empty blockchain for use by the test.
 447
 448         Create an empty blockchain and num_nodes wallets.
 449         Useful if a test case wants complete control over initialization."""
 450         for i in range(self.num_nodes):
 451             initialize_datadir(self.options.tmpdir, i)
 452
 453 class ComparisonTestFramework(BitcoinTestFramework):
 454     """Test framework for doing p2p comparison testing
 455
 456     Sets up some bitcoind binaries:
 457     - 1 binary: test binary
 458     - 2 binaries: 1 test binary, 1 ref binary
 459     - n>2 binaries: 1 test binary, n-1 ref binaries"""
 460
 461     def set_test_params(self):
 462         self.num_nodes = 2
 463         self.setup_clean_chain = True
 464
 465     def add_options(self, parser):
 466         parser.add_option("--testbinary", dest="testbinary",
 467                           default=os.getenv("BITCOIND", "bitcoind"),
 468                           help="bitcoind binary to test")
 469         parser.add_option("--refbinary", dest="refbinary",
 470                           default=os.getenv("BITCOIND", "bitcoind"),
 471                           help="bitcoind binary to use for reference nodes (if any)")
 472
 473     def setup_network(self):
 474         extra_args = [['-whitelist=127.0.0.1']] * self.num_nodes
 475         if hasattr(self, "extra_args"):
 476             extra_args = self.extra_args
 477         self.add_nodes(self.num_nodes, extra_args,
 478                        binary=[self.options.testbinary] +
 479                        [self.options.refbinary] * (self.num_nodes - 1))
 480         self.start_nodes()
 481
 482 class SkipTest(Exception):
 483     """This exception is raised to skip a test"""
 484     def __init__(self, message):
 485         self.message = message