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