Merge #10017: combine_logs.py - aggregates log files from multiple bitcoinds during functional tests.

8317a45 Python functional tests should log in UTC (John Newbery)
61d75f5 Introduce combine_logs.py to combine log files from multiple bitcoinds. (John Newbery)

Tree-SHA512: 472a00907c938cd558353086eda0fbd8746a889680d5db4900eb95496f5f6a12eeb46560a5efd4bbfee10c85307fcf50d021356c5aad64168eb5cc2ababb073a

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] <test temporary directory>', 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()

test/functional/combined_log_template.html

@@ -0,0 +1,40 @@
+<html lang="en">
+<head>
+    <title> {{ title }} </title>
+    <style>
+        ul {
+            list-style-type: none;
+            font-family: monospace;
+        }
+        li {
+            border: 1px solid slategray;
+            margin-bottom: 1px;
+        }
+        li:hover {
+            filter: brightness(85%);
+        }
+        li.log-test {
+            background-color: cyan;
+        }
+        li.log-node0 {
+            background-color: lightblue;
+        }
+        li.log-node1 {
+            background-color: lightgreen;
+        }
+        li.log-node2 {
+            background-color: lightsalmon;
+        }
+        li.log-node3 {
+            background-color: lightyellow;
+        }
+    </style>
+</head>
+<body>
+<ul>
+{% for event in log_events %}
+<li class="log-{{ event.source }}"> {{ event.source }} {{ event.timestamp }} {{event.event}}</li>
+{% endfor %}
+</ul>
+</body>
+</html>

test/functional/test_framework/test_framework.py

@@ -10,6 +10,7 @@ import os
 import sys
 import shutil
 import tempfile
+import time
 import traceback
 from concurrent.futures import ThreadPoolExecutor
 from time import time, sleep
@@ -222,6 +223,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