Suppress noisy output from qa tests in Travis

jnewbery commented at 8:14 pm on February 16, 2017: member

The QA tests are currently quite noisy even when they run successfully. They output progress information which fills up pages of screen. This might be what you want when running the tests locally, but for build/integration tools it fills the output log with spam.

This PR suppresses noisy output from the qa tests. It builds on and requires both #9657 and #9768. There are three commits specifically for this PR:

commit 1 adds a ‘quiet’ option to rpc-tests.py, which suppresses the progress output to stdout.
commit 2 updates .travis.yml to use quiet mode
commit 3 prints out the final 1000 lines of test_framework.log if the test fails.

Example of a successful travis run: https://travis-ci.org/jnewbery/bitcoin/jobs/202373787 Example of a failed travis run: https://travis-ci.org/jnewbery/bitcoin/jobs/202374810

in qa/pull-tester/rpc-tests.py: in 18f991b894 outdated

147@@ -146,6 +148,13 @@ def main():
148     config = configparser.ConfigParser()
149     config.read_file(open(os.path.dirname(__file__) + "/tests_config.ini"))
150 
151+    # Set up logging handler
152+    sh = logging.StreamHandler()
153+    sh.setLevel((logging.INFO if args.quiet else logging.DEBUG))

ryanofsky commented at 10:17 pm on February 16, 2017:

Maybe only call sh.setLevel if args.quiet is true, because logging.DEBUG can still throw away logs at levels < 10.

in qa/rpc-tests/test_framework/test_framework.py: in d580707d6a outdated

182-                    from collections import deque
183-                    print("".join(deque(open(f), MAX_LINES_TO_PRINT)))
184+                    try:
185+                        print("From" , f, ":")
186+                        print("".join(deque(open(f), MAX_LINES_TO_PRINT)))
187+                    except:

ryanofsky commented at 10:26 pm on February 16, 2017:

I think this very broad exception handler could hide information we might like to know about. I would remove it, or narrow it, or at least at stick a “traceback.print_exc()” call in here.

If this handler is supposed to handle the case where f does not exist, you could add an “if os.path.exists(f)” or similar check above.

jnewbery commented at 6:45 pm on March 15, 2017:

Printing the tails of the log files here is simply to help if the test case fails on travis. My thinking in adding the try/except handling is that if reading a log file fails for any reason, we should just continue and try to print out the other log files. I don’t want there to be any chance that this commit makes the logging available on travis any worse.

I’ve added a print out of the stack trace exception in the except branch. Does that allay your concerns here?

ryanofsky commented at 6:59 pm on March 15, 2017:

The print addresses most of my concern. If something goes wrong, I would prefer to know about it.

I also think you should change the bare except to except OSError or except Exception. It isn’t right to ignore exceptions like SystemExit or KeyboardInterrupt and keep looping if someone is trying to kill the program. (For reference: https://docs.python.org/3/library/exceptions.html#exception-hierarchy)

jtimon commented at 2:37 pm on March 21, 2017:

Agree on catching only a more concrete exception, specially if you’re expecting one in particular, as it seems to be the case in https://github.com/bitcoin/bitcoin/pull/9780/commits/a2a565180449b80c054c05c12c93097f1e8752c2 . Also you could print the message of the exception too (before the traceback).

fanquake added the label Tests on Feb 17, 2017

laanwj commented at 8:09 am on February 17, 2017: member

Concept ACK, filtering signal/noise has been a pet peeve of me for as long as we have a travis run, but never got around to it. Thanks for doing this.

JeremyRubin commented at 8:27 am on February 17, 2017: contributor

I like the approach, but I think that it would be preferable to have some output (e.g., periods) while the tests are running. This is because of a limitation in Travis CI where if no output is seen for 10 minutes the build will fail. This has been a problem historically in the unit tests, but was only addressed (by me) by making them run more quickly such that this is not an issue.

laanwj commented at 10:10 am on February 17, 2017: member

Yes, printing periods or another kind of progress display would be nice. My issue is with tons of unnecessary debug output.

Edit: But don’t we already do that during the RPC tests, printing periods?

ryanofsky commented at 11:12 am on February 17, 2017: member

utACK d580707d6a2481f13e8c83c08b5635c59672ae6d

jnewbery commented at 9:51 pm on February 17, 2017: member

@laanwj - this PR suppresses the period printing when running –quiet mode. Do you want me to put that back in?

laanwj commented at 9:21 am on February 18, 2017: member

this PR suppresses the period printing when running –quiet mode. Do you want me to put that back in?

Not necessarily. Just in the mode that Travis uses, apparently it needs to print something (and dots are better than text spam :-) to avoid the timeout problem that @JeremyRubin mentions.

jnewbery force-pushed on Feb 23, 2017

jnewbery commented at 9:38 pm on February 23, 2017: member

I’ve rebased this now that #9657 has been merged. I’ve also made a change so that period printing still happens in quiet mode. That should prevent any Travis timeout issues.

ryanofsky commented at 6:52 pm on March 8, 2017: member

re-utACK 85312c075e7bf3379e0a277e3393e734f940b71c. Confirmed no changes since last rebase other than restoring the print(’.’).

I would definitely prefer not to be adding the catch-all except handler here, though: #9780 (review)

jnewbery force-pushed on Mar 15, 2017

jnewbery commented at 6:46 pm on March 15, 2017: member

rebased and addressed #9780 (review).

jtimon commented at 2:38 pm on March 21, 2017: contributor

utACK a2a565180449b80c054c05c12c93097f1e8752c2 except for @ryanofsky ’s nit. Needs rebase.

jnewbery force-pushed on Mar 21, 2017

jnewbery commented at 3:03 pm on March 21, 2017: member

Updated the exception handler to catch only OSError exceptions as suggested by @ryanofsky and rebased.

jtimon commented at 1:11 pm on March 25, 2017: contributor

Needs rebase again.

jnewbery force-pushed on Mar 27, 2017

Add --quiet option to suppress rpc-tests.py output

rpt-tests.py outputs progress information as it runs tests. This commit
adds a --quiet option that suppresses that progress output and only
prints a summary of results (and logs from failed tests).

55992f1302

Update travis config to run rpc-tests.py in quiet mode 6d780b1b0c

jnewbery force-pushed on Mar 27, 2017

jnewbery commented at 3:58 pm on March 27, 2017: member

rebased. I think this is useful PR since it suppresses noisy output in travis when tests pass and also increases the amount of logging available when the test fails. This will be helpful in debugging intermittent functional test failures in Travis. @MarcoFalke , @laanwj - can I convince you to review this PR?

laanwj commented at 5:36 pm on March 27, 2017: member

utACK 2c0be25

MarcoFalke commented at 10:26 pm on March 27, 2017: member

utACK 2c0be25bd6b744cab60a3672409750545522733a. Please squash the fixup commit.

Print out the final 1000 lines of test_framework.log if test fails 8c7288c06b

jnewbery force-pushed on Mar 27, 2017

jnewbery commented at 11:34 pm on March 27, 2017: member

squashed

MarcoFalke merged this on Mar 28, 2017

MarcoFalke closed this on Mar 28, 2017

MarcoFalke referenced this in commit c412fd805d on Mar 28, 2017

codablock referenced this in commit 8348ff845e on Jun 18, 2019

PastaPastaPasta referenced this in commit 9c863edd9c on Jun 18, 2019

barrystyle referenced this in commit e8ce24187b on Jan 22, 2020

MarcoFalke locked this on Sep 8, 2021

Suppress noisy output from qa tests in Travis #9780