1 #!/usr/bin/env python3
2 # Copyright (c) 2017-present 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 """Combine logs from multiple bitcoin nodes as well as the test_framework log.
6 7 This streams the combined log output to stdout. Use combine_logs.py > outputfile
8 to write to an outputfile.
9 10 If no argument is provided, the most recent test directory will be used."""
11 12 import argparse
13 from collections import defaultdict, namedtuple
14 import heapq
15 import itertools
16 import os
17 import pathlib
18 import re
19 import sys
20 import tempfile
21 22 # N.B.: don't import any local modules here - this script must remain executable
23 # without the parent module installed.
24 25 # Should match same symbol in `test_framework.test_framework`.
26 TMPDIR_PREFIX = "bitcoin_func_test_"
27 28 # Matches on the date format at the start of the log event
29 TIMESTAMP_PATTERN = re.compile(r"^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}(\.\d{6})?Z")
30 31 LogEvent = namedtuple('LogEvent', ['timestamp', 'source', 'event'])
32 33 def main():
34 """Main function. Parses args, reads the log files and renders them as text or html."""
35 parser = argparse.ArgumentParser(
36 description=__doc__, formatter_class=argparse.RawTextHelpFormatter)
37 parser.add_argument(
38 'testdir', nargs='?', default='',
39 help=('temporary test directory to combine logs from. '
40 'Defaults to the most recent'))
41 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)')
42 parser.add_argument('--html', dest='html', action='store_true', help='outputs the combined log as html. Requires jinja2. pip install jinja2')
43 args = parser.parse_args()
44 45 if args.html and args.color:
46 print("Only one out of --color or --html should be specified")
47 sys.exit(1)
48 49 testdir = args.testdir or find_latest_test_dir()
50 51 if not testdir:
52 print("No test directories found")
53 sys.exit(1)
54 55 if not args.testdir:
56 print("Opening latest test directory: {}".format(testdir), file=sys.stderr)
57 58 colors = defaultdict(lambda: '')
59 if args.color:
60 colors["test"] = "\033[0;36m" # CYAN
61 colors["node0"] = "\033[0;34m" # BLUE
62 colors["node1"] = "\033[0;32m" # GREEN
63 colors["node2"] = "\033[0;31m" # RED
64 colors["node3"] = "\033[0;33m" # YELLOW
65 colors["reset"] = "\033[0m" # Reset font color
66 67 log_events = read_logs(testdir)
68 69 if args.html:
70 print_logs_html(log_events)
71 else:
72 print_logs_plain(log_events, colors)
73 print_node_warnings(testdir, colors)
74 75 76 def read_logs(tmp_dir):
77 """Reads log files.
78 79 Delegates to generator function get_log_events() to provide individual log events
80 for each of the input log files."""
81 82 # Find out what the folder is called that holds node 0's debug.log file
83 debug_logs = list(pathlib.Path(tmp_dir).glob('node0/**/debug.log'))
84 match len(debug_logs):
85 case 0:
86 chain = 'regtest' # fallback to regtest
87 case 1:
88 chain = re.search(r'node0/(.+?)/debug\.log$', debug_logs[0].as_posix()).group(1)
89 case _:
90 raise RuntimeError('Max one debug.log is supported, found several:\n\t' +
91 '\n\t'.join(map(str, debug_logs)))
92 93 files = [("test", "%s/test_framework.log" % tmp_dir)]
94 for i in itertools.count():
95 logfile = "{}/node{}/{}/debug.log".format(tmp_dir, i, chain)
96 if not os.path.isfile(logfile):
97 break
98 files.append(("node%d" % i, logfile))
99 100 return heapq.merge(*[get_log_events(source, f) for source, f in files])
101 102 103 def print_node_warnings(tmp_dir, colors):
104 """Print nodes' errors and warnings"""
105 106 warnings = []
107 for stream in ['stdout', 'stderr']:
108 for i in itertools.count():
109 folder = "{}/node{}/{}".format(tmp_dir, i, stream)
110 if not os.path.isdir(folder):
111 break
112 for (_, _, fns) in os.walk(folder):
113 for fn in fns:
114 warning = pathlib.Path('{}/{}'.format(folder, fn)).read_text().strip()
115 if warning:
116 warnings.append(("node{} {}".format(i, stream), warning))
117 118 print()
119 for w in warnings:
120 print("{} {} {} {}".format(colors[w[0].split()[0]], w[0], w[1], colors["reset"]))
121 122 123 def find_latest_test_dir():
124 """Returns the latest tmpfile test directory prefix."""
125 tmpdir = tempfile.gettempdir()
126 127 def join_tmp(basename):
128 return os.path.join(tmpdir, basename)
129 130 def is_valid_test_tmpdir(basename):
131 fullpath = join_tmp(basename)
132 return (
133 os.path.isdir(fullpath)
134 and basename.startswith(TMPDIR_PREFIX)
135 and os.access(fullpath, os.R_OK)
136 )
137 138 testdir_paths = [
139 join_tmp(name) for name in os.listdir(tmpdir) if is_valid_test_tmpdir(name)
140 ]
141 142 return max(testdir_paths, key=os.path.getmtime) if testdir_paths else None
143 144 145 def get_log_events(source, logfile):
146 """Generator function that returns individual log events.
147 148 Log events may be split over multiple lines. We use the timestamp
149 regex match as the marker for a new log event."""
150 try:
151 with open(logfile, 'r') as infile:
152 event = ''
153 timestamp = ''
154 for line in infile:
155 # skip blank lines
156 if line == '\n':
157 continue
158 # if this line has a timestamp, it's the start of a new log event.
159 time_match = TIMESTAMP_PATTERN.match(line)
160 if time_match:
161 if event:
162 yield LogEvent(timestamp=timestamp, source=source, event=event.rstrip())
163 timestamp = time_match.group()
164 if time_match.group(1) is None:
165 # timestamp does not have microseconds. Add zeroes.
166 timestamp_micro = timestamp.replace("Z", ".000000Z")
167 line = line.replace(timestamp, timestamp_micro)
168 timestamp = timestamp_micro
169 event = line
170 # if it doesn't have a timestamp, it's a continuation line of the previous log.
171 else:
172 # Add the line. Prefix with space equivalent to the source + timestamp so log lines are aligned
173 event += " " + line
174 # Flush the final event
175 yield LogEvent(timestamp=timestamp, source=source, event=event.rstrip())
176 except FileNotFoundError:
177 print("File %s could not be opened. Continuing without it." % logfile, file=sys.stderr)
178 179 180 def print_logs_plain(log_events, colors):
181 """Renders the iterator of log events into text."""
182 for event in log_events:
183 lines = event.event.splitlines()
184 print("{0} {1: <5} {2} {3}".format(colors[event.source.rstrip()], event.source, lines[0], colors["reset"]))
185 if len(lines) > 1:
186 for line in lines[1:]:
187 print("{0}{1}{2}".format(colors[event.source.rstrip()], line, colors["reset"]))
188 189 190 def print_logs_html(log_events):
191 """Renders the iterator of log events into html."""
192 try:
193 import jinja2 #type:ignore
194 except ImportError:
195 print("jinja2 not found. Try `pip install jinja2`")
196 sys.exit(1)
197 print(jinja2.Environment(loader=jinja2.FileSystemLoader('./'))
198 .get_template('combined_log_template.html')
199 .render(title="Combined Logs from testcase", log_events=[event._asdict() for event in log_events]))
200 201 202 if __name__ == '__main__':
203 main()
204