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