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()