From 61d75f587de504310c07216c4755cd206e31dc09 Mon Sep 17 00:00:00 2001 From: John Newbery Date: Fri, 24 Feb 2017 16:42:04 -0500 Subject: [PATCH 1/2] Introduce combine_logs.py to combine log files from multiple bitcoinds. This commit adds a tool for combining log files from multiple instances of bitcoinds as well as the test_framework.log file. This gives a combined view of what the test framework and all bitcoin instances were doing during a qa test. --- test/functional/combine_logs.py | 111 +++++++++++++++++++++ test/functional/combined_log_template.html | 40 ++++++++ 2 files changed, 151 insertions(+) create mode 100755 test/functional/combine_logs.py create mode 100644 test/functional/combined_log_template.html diff --git a/test/functional/combine_logs.py b/test/functional/combine_logs.py new file mode 100755 index 0000000000..0c2f60172f --- /dev/null +++ b/test/functional/combine_logs.py @@ -0,0 +1,111 @@ +#!/usr/bin/env python3 +"""Combine logs from multiple bitcoin nodes as well as the test_framework log. + +This streams the combined log output to stdout. Use combine_logs.py > outputfile +to write to an outputfile.""" + +import argparse +from collections import defaultdict, namedtuple +import glob +import heapq +import os +import re +import sys + +# Matches on the date format at the start of the log event +TIMESTAMP_PATTERN = re.compile(r"^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d{6}") + +LogEvent = namedtuple('LogEvent', ['timestamp', 'source', 'event']) + +def main(): + """Main function. Parses args, reads the log files and renders them as text or html.""" + + parser = argparse.ArgumentParser(usage='%(prog)s [options] ', description=__doc__) + parser.add_argument('-c', '--color', dest='color', action='store_true', help='outputs the combined log with events colored by source (requires posix terminal colors. Use less -r for viewing)') + parser.add_argument('--html', dest='html', action='store_true', help='outputs the combined log as html. Requires jinja2. pip install jinja2') + args, unknown_args = parser.parse_known_args() + + if args.color and os.name != 'posix': + print("Color output requires posix terminal colors.") + sys.exit(1) + + if args.html and args.color: + print("Only one out of --color or --html should be specified") + sys.exit(1) + + # There should only be one unknown argument - the path of the temporary test directory + if len(unknown_args) != 1: + print("Unexpected arguments" + str(unknown_args)) + sys.exit(1) + + log_events = read_logs(unknown_args[0]) + + print_logs(log_events, color=args.color, html=args.html) + +def read_logs(tmp_dir): + """Reads log files. + + Delegates to generator function get_log_events() to provide individual log events + for each of the input log files.""" + + files = [("test", "%s/test_framework.log" % tmp_dir)] + for i, logfile in enumerate(glob.glob("%s/node*/regtest/debug.log" % tmp_dir)): + files.append(("node%d" % i, logfile)) + + return heapq.merge(*[get_log_events(source, f) for source, f in files]) + +def get_log_events(source, logfile): + """Generator function that returns individual log events. + + Log events may be split over multiple lines. We use the timestamp + regex match as the marker for a new log event.""" + try: + with open(logfile, 'r') as infile: + event = '' + timestamp = '' + for line in infile: + # skip blank lines + if line == '\n': + continue + # if this line has a timestamp, it's the start of a new log event. + time_match = TIMESTAMP_PATTERN.match(line) + if time_match: + if event: + yield LogEvent(timestamp=timestamp, source=source, event=event.rstrip()) + event = line + timestamp = time_match.group() + # if it doesn't have a timestamp, it's a continuation line of the previous log. + else: + event += "\n" + line + # Flush the final event + yield LogEvent(timestamp=timestamp, source=source, event=event.rstrip()) + except FileNotFoundError: + print("File %s could not be opened. Continuing without it." % logfile, file=sys.stderr) + +def print_logs(log_events, color=False, html=False): + """Renders the iterator of log events into text or html.""" + if not html: + colors = defaultdict(lambda: '') + if color: + colors["test"] = "\033[0;36m" # CYAN + colors["node0"] = "\033[0;34m" # BLUE + colors["node1"] = "\033[0;32m" # GREEN + colors["node2"] = "\033[0;31m" # RED + colors["node3"] = "\033[0;33m" # YELLOW + colors["reset"] = "\033[0m" # Reset font color + + for event in log_events: + print("{0} {1: <5} {2} {3}".format(colors[event.source.rstrip()], event.source, event.event, colors["reset"])) + + else: + try: + import jinja2 + except ImportError: + print("jinja2 not found. Try `pip install jinja2`") + sys.exit(1) + print(jinja2.Environment(loader=jinja2.FileSystemLoader('./')) + .get_template('combined_log_template.html') + .render(title="Combined Logs from testcase", log_events=[event._asdict() for event in log_events])) + +if __name__ == '__main__': + main() diff --git a/test/functional/combined_log_template.html b/test/functional/combined_log_template.html new file mode 100644 index 0000000000..c0b854b080 --- /dev/null +++ b/test/functional/combined_log_template.html @@ -0,0 +1,40 @@ + + + {{ title }} + + + + + + From 8317a4516102d95c7e45c3b61e33faa84346eb61 Mon Sep 17 00:00:00 2001 From: John Newbery Date: Tue, 21 Mar 2017 10:05:59 -0400 Subject: [PATCH 2/2] Python functional tests should log in UTC bitcoind logs use UTC. Python functional tests should also log in UTC. --- test/functional/test_framework/test_framework.py | 2 ++ 1 file changed, 2 insertions(+) diff --git a/test/functional/test_framework/test_framework.py b/test/functional/test_framework/test_framework.py index d7072fa78d..fd2e803541 100755 --- a/test/functional/test_framework/test_framework.py +++ b/test/functional/test_framework/test_framework.py @@ -10,6 +10,7 @@ import os import sys import shutil import tempfile +import time import traceback from .util import ( @@ -202,6 +203,7 @@ class BitcoinTestFramework(object): 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') + formatter.converter = time.gmtime fh.setFormatter(formatter) ch.setFormatter(formatter) # add the handlers to the logger