1  #!/usr/bin/env python3
  2  # Copyright (c) 2017-2021 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 the debug.log file
 83      glob = pathlib.Path(tmp_dir).glob('node0/**/debug.log')
 84      path = next(glob, None)
 85      if path:
 86          assert next(glob, None) is None #  more than one debug.log, should never happen
 87          chain = re.search(r'node0/(.+?)/debug\.log$', path.as_posix()).group(1)  # extract the chain name
 88      else:
 89          chain = 'regtest'  # fallback to regtest (should only happen when none exists)
 90  
 91      files = [("test", "%s/test_framework.log" % tmp_dir)]
 92      for i in itertools.count():
 93          logfile = "{}/node{}/{}/debug.log".format(tmp_dir, i, chain)
 94          if not os.path.isfile(logfile):
 95              break
 96          files.append(("node%d" % i, logfile))
 97  
 98      return heapq.merge(*[get_log_events(source, f) for source, f in files])
 99  
100  
101  def print_node_warnings(tmp_dir, colors):
102      """Print nodes' errors and warnings"""
103  
104      warnings = []
105      for stream in ['stdout', 'stderr']:
106          for i in itertools.count():
107              folder = "{}/node{}/{}".format(tmp_dir, i, stream)
108              if not os.path.isdir(folder):
109                  break
110              for (_, _, fns) in os.walk(folder):
111                  for fn in fns:
112                      warning = pathlib.Path('{}/{}'.format(folder, fn)).read_text().strip()
113                      if warning:
114                          warnings.append(("node{} {}".format(i, stream), warning))
115  
116      print()
117      for w in warnings:
118          print("{} {} {} {}".format(colors[w[0].split()[0]], w[0], w[1], colors["reset"]))
119  
120  
121  def find_latest_test_dir():
122      """Returns the latest tmpfile test directory prefix."""
123      tmpdir = tempfile.gettempdir()
124  
125      def join_tmp(basename):
126          return os.path.join(tmpdir, basename)
127  
128      def is_valid_test_tmpdir(basename):
129          fullpath = join_tmp(basename)
130          return (
131              os.path.isdir(fullpath)
132              and basename.startswith(TMPDIR_PREFIX)
133              and os.access(fullpath, os.R_OK)
134          )
135  
136      testdir_paths = [
137          join_tmp(name) for name in os.listdir(tmpdir) if is_valid_test_tmpdir(name)
138      ]
139  
140      return max(testdir_paths, key=os.path.getmtime) if testdir_paths else None
141  
142  
143  def get_log_events(source, logfile):
144      """Generator function that returns individual log events.
145  
146      Log events may be split over multiple lines. We use the timestamp
147      regex match as the marker for a new log event."""
148      try:
149          with open(logfile, 'r', encoding='utf-8') as infile:
150              event = ''
151              timestamp = ''
152              for line in infile:
153                  # skip blank lines
154                  if line == '\n':
155                      continue
156                  # if this line has a timestamp, it's the start of a new log event.
157                  time_match = TIMESTAMP_PATTERN.match(line)
158                  if time_match:
159                      if event:
160                          yield LogEvent(timestamp=timestamp, source=source, event=event.rstrip())
161                      timestamp = time_match.group()
162                      if time_match.group(1) is None:
163                          # timestamp does not have microseconds. Add zeroes.
164                          timestamp_micro = timestamp.replace("Z", ".000000Z")
165                          line = line.replace(timestamp, timestamp_micro)
166                          timestamp = timestamp_micro
167                      event = line
168                  # if it doesn't have a timestamp, it's a continuation line of the previous log.
169                  else:
170                      # Add the line. Prefix with space equivalent to the source + timestamp so log lines are aligned
171                      event += "                                   " + line
172              # Flush the final event
173              yield LogEvent(timestamp=timestamp, source=source, event=event.rstrip())
174      except FileNotFoundError:
175          print("File %s could not be opened. Continuing without it." % logfile, file=sys.stderr)
176  
177  
178  def print_logs_plain(log_events, colors):
179      """Renders the iterator of log events into text."""
180      for event in log_events:
181          lines = event.event.splitlines()
182          print("{0} {1: <5} {2} {3}".format(colors[event.source.rstrip()], event.source, lines[0], colors["reset"]))
183          if len(lines) > 1:
184              for line in lines[1:]:
185                  print("{0}{1}{2}".format(colors[event.source.rstrip()], line, colors["reset"]))
186  
187  
188  def print_logs_html(log_events):
189      """Renders the iterator of log events into html."""
190      try:
191          import jinja2 #type:ignore
192      except ImportError:
193          print("jinja2 not found. Try `pip install jinja2`")
194          sys.exit(1)
195      print(jinja2.Environment(loader=jinja2.FileSystemLoader('./'))
196                      .get_template('combined_log_template.html')
197                      .render(title="Combined Logs from testcase", log_events=[event._asdict() for event in log_events]))
198  
199  
200  if __name__ == '__main__':
201      main()