qa: Combine logs on travis #11779

MarcoFalke commented at 11:22 PM on November 27, 2017: member

Currently, when a functional test fails, the debug logs are printed sequentially to the travis log. This makes debugging race conditions based on the travis log hard. Instead, all logs events should be combined and sorted by their timestamp, then appended to the travis log.

This uses combine_logs.py by @jnewbery

MarcoFalke added the label Tests on Nov 27, 2017

MarcoFalke added the label Docs and Output on Nov 27, 2017

MarcoFalke removed the label Docs and Output on Nov 27, 2017

laanwj commented at 7:23 AM on November 28, 2017: member

Concept ACK

jnewbery commented at 1:05 PM on November 28, 2017: member

Concept ACK. My only concern would be if combine_logs.py wasn't reliable and this could potentially lead to us losing important logging information. However, I've been using combine_logs regularly for 6+ months and haven't had any problems with it yet.

Do you have a branch on top of this where you've introduced a test failure to trigger this in Travis? If so, can you link to it?

MarcoFalke force-pushed on Nov 28, 2017

MarcoFalke commented at 3:14 PM on November 28, 2017: member

@jnewbery You can test locally with

PYTHON_DEBUG=1 ./test/functional/test_runner.py

An example run would be any of the red ones out of https://travis-ci.org/bitcoin/bitcoin/builds/308465667

in test/functional/test_framework/test_framework.py:152 in fa043b458e outdated

 161 | -                            print("From", fn, ":")
 162 | -                            print("".join(deque(f, MAX_LINES_TO_PRINT)))
 163 | -                    except OSError:
 164 | -                        print("Opening file %s failed." % fn)
 165 | -                        traceback.print_exc()
 166 | +                logging.shutdown()  # Flush handlers

jnewbery commented at 4:36 PM on November 28, 2017:

Python reference: https://docs.python.org/3/library/logging.html#logging.shutdown :

This should be called at application exit and no further use of the logging system should be made after this call.

You're calling log.info() after this call, and also calling logging.shutdown() a second time.

Perhaps to avoid this, you could move this whole block to below the last call to self.log?

MarcoFalke commented at 5:37 PM on November 28, 2017:

Should be fine. I call sys.exit a few lines below.

in test/functional/test_framework/test_framework.py:155 in fa043b458e outdated

 164 | -                        print("Opening file %s failed." % fn)
 165 | -                        traceback.print_exc()
 166 | +                logging.shutdown()  # Flush handlers
 167 | +                lines = 4000
 168 | +                print()
 169 | +                print('Combine the logs and print the last {} lines ...'.format(lines))

jnewbery commented at 4:38 PM on November 28, 2017:

nit: I have a preference for:

print('\nCombine the logs and print the last {} lines ...\n'.format(lines))

rather than the empty print() function calls.

jnewbery commented at 4:46 PM on November 28, 2017: member

Concept ACK, but I don't much like the idea of calling combine_logs from the test_framework. I think it makes more sense to have separation between the test execution and the log post processing.

I'd say combine_logs should be called either:

directly by Travis (update .travis.yml to scan the tmpdir and call combine_logs on any directories that are there); or
from the test_runner harness when called with a certain argument. You'd need to update the code at https://github.com/bitcoin/bitcoin/blob/26efc220a13aa3413f6e55e311e8991445104f82/test/functional/test_runner.py#L421

I have a preference for (2).

MarcoFalke commented at 5:39 PM on November 28, 2017: member

I think moving it to test_runner.py makes sense. Taking a look...

MarcoFalke force-pushed on Nov 28, 2017

qa: Combine logs on travis by default eeee42c620

MarcoFalke force-pushed on Nov 28, 2017

MarcoFalke commented at 11:06 PM on November 28, 2017: member

Again, there should be red travis failures in https://travis-ci.org/bitcoin/bitcoin/builds/308698327 soon.

Though, I'd recommend to test locally with

TRAVIS=true ./test/functional/test_runner.py

in test/functional/test_runner.py:342 in eeee42c620

 336 | @@ -337,6 +337,18 @@ def run_tests(test_list, src_dir, build_dir, exeext, tmpdir, jobs=1, enable_cove
 337 |      # Clear up the temp directory if all subdirectories are gone
 338 |      if not os.listdir(tmpdir):
 339 |          os.rmdir(tmpdir)
 340 | +    elif os.getenv("TRAVIS", "") == "true":
 341 | +        # Print the logs on travis, so they are preserved when the vm is disposed
 342 | +        LINES_PRINT_TRAVIS = 4000

promag commented at 11:31 PM on November 28, 2017:

Move to .travis.yml?

laanwj commented at 10:40 AM on November 29, 2017:

You mean, make LINES_PRINT_TRAVIS the environment variable instead of TRAVIS?

laanwj commented at 10:41 AM on November 29, 2017:

Could it be useful to have this as a general command line option, instead of a hidden environment variable? (no need to do in this PR, the integration just seems fairly useful)

MarcoFalke commented at 3:59 PM on November 29, 2017:

Yes, adding that feature to parse the max_lines in combine_logs is useful, but totally out of scope of this pull. This code branch was only ever executed on travis and presumably by no developer. My goal here is to combine the logs on travis to debug travis specific failures. I think placing that constant right here in the code is compact and eases code review.

Bikeshedding and new features should be submitted in separate pull request.

promag commented at 4:46 PM on November 29, 2017:

My point is if in the future this value needs to be changed then a change to travis config would sound better. A nit really.

promag commented at 11:31 PM on November 28, 2017: member

Concept ACK.

Nit, update test/functional/combine_logs.py description?

MarcoFalke renamed this:
~~qa: Combine logs on travis by default~~
qa: Combine logs on travis
on Nov 29, 2017

jnewbery commented at 4:31 PM on November 29, 2017: member

This is better. I think it can be improved further as follows:

no need to modify combine_logs to be an importable module - we can just call it as a subprocess from test_runner.
this prints out the combined logs after the summary table of results. It's useful to have those results at the bottom so it's very quick to see which tests have failed at a glance.
as @laanwj points out, it's better to decouple this new functionality and put it behind a command line argument, rather than rely on the travis environment variable. That's not such a big change and I think it makes sense to include it in this PR.

I've implemented those changes here: https://github.com/jnewbery/bitcoin/tree/pr11779.1 . Let me know what you think.

MarcoFalke commented at 5:13 PM on November 29, 2017: member

@jnewbery Awesome! Thanks for picking this up. Mind to submit a pull for that?

MarcoFalke closed this on Nov 29, 2017

MarcoFalke deleted the branch on Nov 29, 2017

jnewbery commented at 5:25 PM on November 29, 2017: member

Awesome! Thanks for picking this up. Mind to submit a pull for that?

I didn't realise suggesting changes implied I'd picked this up! :slightly_frowning_face:

jnewbery commented at 5:32 PM on November 29, 2017: member

as discussed, I'll open a new PR

laanwj referenced this in commit 60d739eb49 on Nov 30, 2017

MarcoFalke locked this on Sep 8, 2021