From 0e6d23dd53488700e42ca08eafddcea0b6616564 Mon Sep 17 00:00:00 2001 From: John Newbery Date: Wed, 15 Feb 2017 11:36:46 -0500 Subject: [PATCH] Add logging to test_framework.py This commit adds python logging to test_framework.py. By default this will output all log levels (DEBUG-INFO-WARNING-ERROR-CRITICAL) to a test_framework.log file in the temporary test directory, and higher level logs (WARNING-ERROR-CRITICAL) to the console. The level of logging to the console can be controlled by a new log-level parameter. This should have no interaction with the existing trace-rpc parameter. --- qa/rpc-tests/test_framework/test_framework.py | 66 +++++++++++++------ 1 file changed, 46 insertions(+), 20 deletions(-) diff --git a/qa/rpc-tests/test_framework/test_framework.py b/qa/rpc-tests/test_framework/test_framework.py index c5e9c6a658..024290237e 100755 --- a/qa/rpc-tests/test_framework/test_framework.py +++ b/qa/rpc-tests/test_framework/test_framework.py @@ -42,7 +42,7 @@ class BitcoinTestFramework(object): pass def setup_chain(self): - print("Initializing test directory "+self.options.tmpdir) + self.log.info("Initializing test directory "+self.options.tmpdir) if self.setup_clean_chain: initialize_chain_clean(self.options.tmpdir, self.num_nodes) else: @@ -112,6 +112,8 @@ class BitcoinTestFramework(object): help="Directory for caching pregenerated datadirs") parser.add_option("--tmpdir", dest="tmpdir", default=tempfile.mkdtemp(prefix="test"), help="Root directory for datadirs") + parser.add_option("-l", "--loglevel", dest="loglevel", default="INFO", + 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.") parser.add_option("--tracerpc", dest="trace_rpc", default=False, action="store_true", help="Print out all RPC calls as they are made") parser.add_option("--portseed", dest="port_seed", default=os.getpid(), type='int', @@ -124,9 +126,6 @@ class BitcoinTestFramework(object): # backup dir variable for removal at cleanup self.options.root, self.options.tmpdir = self.options.tmpdir, self.options.tmpdir + '/' + str(self.options.port_seed) - if self.options.trace_rpc: - logging.basicConfig(level=logging.DEBUG, stream=sys.stdout) - if self.options.coveragedir: enable_coverage(self.options.coveragedir) @@ -136,41 +135,41 @@ class BitcoinTestFramework(object): check_json_precision() + # Set up temp directory and start logging + os.makedirs(self.options.tmpdir, exist_ok=False) + self._start_logging() + success = False + try: - os.makedirs(self.options.tmpdir, exist_ok=False) self.setup_chain() self.setup_network() self.run_test() success = True except JSONRPCException as e: - print("JSONRPC error: "+e.error['message']) - traceback.print_tb(sys.exc_info()[2]) + self.log.exception("JSONRPC error") except AssertionError as e: - print("Assertion failed: " + str(e)) - traceback.print_tb(sys.exc_info()[2]) + self.log.exception("Assertion failed") except KeyError as e: - print("key not found: "+ str(e)) - traceback.print_tb(sys.exc_info()[2]) + self.log.exception("Key error") except Exception as e: - print("Unexpected exception caught during testing: " + repr(e)) - traceback.print_tb(sys.exc_info()[2]) + self.log.exception("Unexpected exception caught during testing") except KeyboardInterrupt as e: - print("Exiting after " + repr(e)) + self.log.warning("Exiting after keyboard interrupt") if not self.options.noshutdown: - print("Stopping nodes") + self.log.info("Stopping nodes") stop_nodes(self.nodes) else: - print("Note: bitcoinds were not stopped and may still be running") + self.log.info("Note: bitcoinds were not stopped and may still be running") if not self.options.nocleanup and not self.options.noshutdown and success: - print("Cleaning up") + self.log.info("Cleaning up") shutil.rmtree(self.options.tmpdir) if not os.listdir(self.options.root): os.rmdir(self.options.root) else: - print("Not cleaning up dir %s" % self.options.tmpdir) + 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. @@ -182,12 +181,39 @@ class BitcoinTestFramework(object): from collections import deque print("".join(deque(open(f), MAX_LINES_TO_PRINT))) if success: - print("Tests successful") + self.log.info("Tests successful") sys.exit(0) else: - print("Failed") + self.log.error("Test failed. Test logging available at %s/test_framework.log", self.options.tmpdir) + logging.shutdown() sys.exit(1) + def _start_logging(self): + # Add logger and logging handlers + self.log = logging.getLogger('TestFramework') + self.log.setLevel(logging.DEBUG) + # Create file handler to log all messages + fh = logging.FileHandler(self.options.tmpdir + '/test_framework.log') + fh.setLevel(logging.DEBUG) + # Create console handler to log messages to stderr. By default this logs only error messages, but can be configured with --loglevel. + ch = logging.StreamHandler(sys.stdout) + # 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 + ll = int(self.options.loglevel) if self.options.loglevel.isdigit() else self.options.loglevel.upper() + ch.setLevel(ll) + # Format logs the same as bitcoind's debug.log with microprecision (so log files can be concatenated and sorted) + formatter = logging.Formatter(fmt = '%(asctime)s.%(msecs)03d000 %(name)s (%(levelname)s): %(message)s', datefmt='%Y-%m-%d %H:%M:%S') + fh.setFormatter(formatter) + ch.setFormatter(formatter) + # add the handlers to the logger + self.log.addHandler(fh) + self.log.addHandler(ch) + + if self.options.trace_rpc: + rpc_logger = logging.getLogger("BitcoinRPC") + rpc_logger.setLevel(logging.DEBUG) + rpc_handler = logging.StreamHandler(sys.stdout) + rpc_handler.setLevel(logging.DEBUG) + rpc_logger.addHandler(rpc_handler) # Test framework for doing p2p comparison testing, which sets up some bitcoind # binaries: