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

jnewbery commented at 9:33 PM on March 16, 2017: member

This commit adds a proof-of-concept tool for combining log files from multiple instances of bitcoinds as well as the test_framework.log file when running a functional test. This gives a combined view of what the test framework and all bitcoin instances were doing during the test.

There are 3 options for output: plain text, colorized text for posix terminals, and html:

Plaintext:

screenshot from 2017-03-16 17-29-16

Colorized text:

screenshot from 2017-03-16 17-29-44

HTML:

screenshot from 2017-03-16 17-31-40

Possible future enhancements:

add some very simple javascript to the HTML output to allow filtering of log events by source, severity, timestamp, regex, etc.
have the test_runner generate combined logs automatically if a test fails.
have automated build tools like travis to generate and push an html log of a testcase if it fails

fanquake added the label Tests on Mar 17, 2017

laanwj commented at 9:37 AM on March 17, 2017: member

Nice! Concept ACK

practicalswift commented at 10:20 AM on March 17, 2017: contributor

@jnewbery Good stuff! Just a minor nit - consider running flake8 on combine_logs.py and fix the warnings to bring it in line with PEP-8 :-)

These are the warnings:

      1  B901 blind except: statement
      1  E221 multiple spaces before operator
      1  E231 missing whitespace after ','
     10  E251 unexpected spaces around keyword / parameter equals
      5  E261 at least two spaces before inline comment
      6  E262 inline comment should start with '# '
      3  E302 expected 2 blank lines, found 1
     12  E501 line too long (… > 79 characters)
      1  E701 multiple statements on one line (colon)
      1  E999 SyntaxError: invalid syntax

jnewbery force-pushed on Mar 17, 2017

jnewbery commented at 2:24 PM on March 17, 2017: member

Thanks @practicalswift . I've addressed the flake8 warnings except:

4     E302 expected 2 blank lines, found 1
1     E305 expected 2 blank lines after class or function definition, found 1
15    E501 line too long (80 > 79 characters)

which I don't care about.

MarcoFalke commented at 6:28 PM on March 17, 2017: member

Indeed. Really nice!

TheBlueMatt commented at 10:22 PM on March 17, 2017: member

Awesome! Can we get travis to use this when it dumps failed debug logs (I believe its via test_framework.py).

jnewbery commented at 10:42 PM on March 17, 2017: member

@TheBlueMatt that's definitely possible. I'd envision travis pushing the html logs to S3 or similar and printing a link in its build log.

But first things first: this needs a bit of review. Once it's merged we can look at integrating it into our build process.

MarcoFalke commented at 9:45 AM on March 19, 2017: member

Tested double-rainbow ACK

screenshot from 2017-03-19 10-44-05

in qa/pull-tester/combine_logs.py:21 in 9775207f24 outdated

  16 | +TIMESTAMP_PATTERN = re.compile(r"^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d{6}")
  17 | +
  18 | +LogEvent = namedtuple('LogEvent', ['timestamp', 'source', 'event'])
  19 | +
  20 | +def main():
  21 | +    """Main function. Parses args, reads the log files and reners them as text or html."""

paveljanik commented at 11:44 AM on March 19, 2017:

reners -> renders

in qa/pull-tester/combine_logs.py:29 in 9775207f24 outdated

  24 | +    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)')
  25 | +    parser.add_argument('--html', dest='html', action='store_true', help='outputs the combined log as html. Requires jinja2. pip install jinja2')
  26 | +    args, unknown_args = parser.parse_known_args()
  27 | +
  28 | +    if args.color and os.name != 'posix':
  29 | +        print("color output requires posix terminal colors.")

paveljanik commented at 11:45 AM on March 19, 2017:

color -> Color

in qa/pull-tester/combine_logs.py:102 in 9775207f24 outdated

  97 | +        for event in log_events:
  98 | +            print("{0} {1: <5} {2} {3}".format(colors[event.source.rstrip()], event.source, event.event, colors["reset"]))
  99 | +
 100 | +    else:
 101 | +        try:
 102 | +            import jinja2

paveljanik commented at 11:47 AM on March 19, 2017:

This new dependency should be mentioned somewhere.

laanwj commented at 2:37 PM on March 20, 2017:

It's mentioned in the --help message:

parser.add_argument('--html', dest='html', action='store_true', help='outputs the combined log as html. Requires jinja2. pip install jinja2')

As it's only required when --html is provided and not by default I'd say that is enough.

jnewbery commented at 2:47 PM on March 20, 2017:

I agree. HTML rendering is not expected to be the mainline use case. If you do want to render as HTML, the documentation is exactly where it should be, at the point of use (and with instructions on how to resolve the problem):

        try:
            import jinja2
        except ImportError:
            print("jinja2 not found. Try `pip install jinja2`")
            sys.exit(1)

paveljanik commented at 2:49 PM on March 20, 2017:

Yes.

paveljanik commented at 11:50 AM on March 19, 2017: contributor

Concept ACK!

This is nice!

jnewbery commented at 2:48 PM on March 20, 2017: member

Thanks for the review @paveljanik . Nits addressed in https://github.com/bitcoin/bitcoin/pull/10017/commits/af802c8b45f6fa913dcc0442a48343cb75a521e5.

in qa/pull-tester/combine_logs.py:95 in af802c8b45 outdated

  90 | +            colors["test"] = "\033[0;36m"   # CYAN
  91 | +            colors["node0"] = "\033[0;34m"  # BLUE
  92 | +            colors["node1"] = "\033[0;32m"  # GREEN
  93 | +            colors["node2"] = "\033[0;31m"  # RED
  94 | +            colors["node3"] = "\033[0;33m"  # YELLOW
  95 | +            colors["reset"] = "\033[0;0m"   # WHITE

laanwj commented at 11:01 AM on March 21, 2017:

Nit: \033[0m suffices, and the WHITE comment should probably go as the reset-color depends on the terminal settings.

jnewbery commented at 2:07 PM on March 21, 2017:

Thanks - fixed

in qa/pull-tester/combine_logs.py:83 in af802c8b45 outdated

  78 | +                else:
  79 | +                    event += "\n" + line
  80 | +            # Flush the final event
  81 | +            yield LogEvent(timestamp=timestamp, source=source, event=event.rstrip())
  82 | +    except FileNotFoundError:
  83 | +        print("File %s could not be opened. Continuing without it." % logfile, file=sys.stderr)

laanwj commented at 11:30 AM on March 21, 2017:

Not a bug in this tool, but I noticed a divergence with the sorting of messages: logging from the test framework is in local time, logging from the nodes is in UTC. This causes, in Europe, all the test messages to sink to the end. I think all logging should be UTC.

jnewbery commented at 2:07 PM on March 21, 2017:

Yes, you're right - all logging should be in UTC. I've pushed a commit which makes the functional test framework log in UTC. Can you retest with the latest tip?

laanwj approved

laanwj commented at 12:51 PM on March 21, 2017: member

The script needs to be moved for #9956

jnewbery force-pushed on Mar 21, 2017

jnewbery commented at 2:08 PM on March 21, 2017: member

I've rebased and moved the script to /test/functional, addressed @laanwj's nit #10017 (review) and updated logging in the functional test framework to always log in UTC.

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.

61d75f587d

Python functional tests should log in UTC

bitcoind logs use UTC. Python functional tests should also log in UTC.

8317a45161

jnewbery force-pushed on Mar 21, 2017

jnewbery commented at 9:31 PM on March 21, 2017: member

fixup commits squashed https://github.com/jnewbery/bitcoin/tree/pr10017.1 -> https://github.com/jnewbery/bitcoin/tree/pr10017.2

laanwj commented at 11:21 AM on March 22, 2017: member

Re-tested, looks good to me now, everything is in the right order. I think this can turn out to be really useful in debugging synchronization issues. Removing the [POC] tag.

laanwj renamed this:
~~[POC] combine_logs.py - aggregates log files from multiple bitcoinds during functional tests.~~
combine_logs.py - aggregates log files from multiple bitcoinds during functional tests.
on Mar 22, 2017

laanwj merged this on Mar 22, 2017

laanwj closed this on Mar 22, 2017

laanwj referenced this in commit 02d64bd929 on Mar 22, 2017

jnewbery deleted the branch on Sep 24, 2018

PastaPastaPasta referenced this in commit aca289cc66 on Mar 14, 2019

PastaPastaPasta referenced this in commit a68dc7dc3d on May 20, 2019

PastaPastaPasta referenced this in commit 7edb9e15ac on May 21, 2019

PastaPastaPasta referenced this in commit 1a6b9169f0 on May 21, 2019

barrystyle referenced this in commit 39dede799e on Jan 22, 2020

MarcoFalke locked this on Sep 8, 2021