tests: show the progress of functional tests #14504

example: (added the progress index n/m)

1/107 - wallet_hd.py passed, Duration: 27 s
.........................................................................................
2/107 - mining_getblocktemplate_longpoll.py passed, Duration: 72 s
..................................................................
3/107 - feature_maxuploadtarget.py passed, Duration: 78 s

Concept ACK

ACK 90829116645690c2c8b668ecc4ef117897dcb571

utACK 9082911.

utACK https://github.com/bitcoin/bitcoin/pull/14504/commits/90829116645690c2c8b668ecc4ef117897dcb57

You should probably squash the commits though

utACK, seems welcome to have a more elaborate progress display, as this script is long-running

though maybe not in all cases; there's also a valid point to be made that successful tests/compiles/etc should spam the screen/log as little as possible—for example the Duration information is duplicated in the summary table anyway!

wonder if we could do some thing where we re-use the progress line with '\r'? (replacing the ..... with a spinner, for ex.)

quick hack, but illustrates my idea:

diff --git a/test/functional/test_runner.py b/test/functional/test_runner.py
index e5275bed0c17b44dd1a5cff1fd3f4f6322a9818f..6240011da9a5226c7cd6d35e1da2f47f37189a93 100755
--- a/test/functional/test_runner.py
+++ b/test/functional/test_runner.py
@@ -363,16 +363,17 @@ def run_tests(test_list, src_dir, build_dir, tmpdir, jobs=1, enable_coverage=Fal
     max_len_name = len(max(test_list, key=len))
     test_count = len(test_list)
+    clearline = '\r' + (' ' * 78) + '\r'
     for i in range(test_count):
         test_result, testdir, stdout, stderr = job_queue.get_next()
         test_results.append(test_result)
         if test_result.status == "Passed":
-            logging.debug("\n%s/%s - %s%s%s passed, Duration: %s s" % (i + 1, test_count, BOLD[1], test_result.name, BOLD[0], test_result.time))
+            print("%s  %s/%s - %s%s%s passed, Duration: %s s\r" % (clearline, i + 1, test_count, BOLD[1], test_result.name, BOLD[0], test_result.time), end='', flush=True)
         elif test_result.status == "Skipped":
-            logging.debug("\n%s/%s - %s%s%s skipped" % (i + 1, test_count, BOLD[1], test_result.name, BOLD[0]))
+            print("%s  %s/%s - %s%s%s skipped" % (clearline, i + 1, test_count, BOLD[1], test_result.name, BOLD[0]))
         else:
-            print("\n%s/%s - %s%s%s failed, Duration: %s s\n" % (i + 1, test_count, BOLD[1], test_result.name, BOLD[0], test_result.time))
+            print("%s  %s/%s - %s%s%s failed, Duration: %s s" % (clearline, i + 1, test_count, BOLD[1], test_result.name, BOLD[0], test_result.time))
             print(BOLD[1] + 'stdout:\n' + BOLD[0] + stdout + '\n')
             print(BOLD[1] + 'stderr:\n' + BOLD[0] + stderr + '\n')
             if combined_logs_len and os.path.isdir(testdir):
@@ -433,6 +434,8 @@ def print_results(test_results, max_len_name, runtime):
     results += "Runtime: %s s\n" % (runtime)
     print(results)
+SPINNER = '|/-\\'
+
 class TestHandler:
     """
     Trigger the test scripts passed in via the list.
@@ -471,6 +474,7 @@ class TestHandler:
                               log_stderr))
         if not self.jobs:
             raise IndexError('pop from empty list')
+        spin = 0
         while True:
             # Return first proc that finishes
             time.sleep(.5)
@@ -493,7 +497,8 @@ class TestHandler:
                     self.jobs.remove(job)
                     return TestResult(name, status, int(time.time() - start_time)), testdir, stdout, stderr
-            print('.', end='', flush=True)
+            print(SPINNER[spin] + '\r', end='', flush=True)
+            spin = (spin + 1) % len(SPINNER)
     def kill_and_join(self):
         """Send SIGKILL to all jobs and block until all have ended."""

If we go the spinning route we'll have to make sure we spin only in cases where the spinner characters and \r don't show up in foo.txt when doing test_runner.py > foo.txt :-)

@laanwj I tried to show the spinner, but the effect was a boring user experience, not seeing the progress of the current functional test https://github.com/isghe/bitcoin/commit/4a41f8e226fbfeeb96e234a677b7b28e1f5cc7a3

So now the dots are shown only for the current test in progress, "deleting" the line of dots from the previous test https://github.com/bitcoin/bitcoin/pull/14504/commits/2b3c35c25032db5cacc01c4ebba56725123344c1:

$ test/functional/test_runner.py -t can_trash
Temporary test directory at can_trash/test_runner_₿_🏃_20181018_220600
1/105 - wallet_hd.py passed, Duration: 21 s
2/105 - mining_getblocktemplate_longpoll.py passed, Duration: 71 s                                 
3/105 - feature_maxuploadtarget.py passed, Duration: 68 s
..................

It also does not show the dots if --quiet arg is set https://github.com/bitcoin/bitcoin/pull/14504/commits/cc9c6162d4ece3f0f448a5c3d72063508ce4bcf4

@isghe please squash your commits

@fanquake squashed

Here's what the output currently looks like.

test/functional/test_runner.py
Temporary test directory at /var/folders/z2/cn877pxd3czdfh47mfkmbwgm0000gn/T/test_runner_₿_🏃_20181020_143946
1/106 - wallet_hd.py passed, Duration: 12 s
................

test/functional/test_runner.py
Temporary test directory at /var/folders/z2/cn877pxd3czdfh47mfkmbwgm0000gn/T/test_runner_₿_🏃_20181020_143946
1/106 - wallet_hd.py passed, Duration: 12 s
2/106 - mining_getblocktemplate_longpoll.py passed, Duration: 68 s                                              
3/106 - feature_maxuploadtarget.py passed, Duration: 62 s
4/106 - wallet_backup.py passed, Duration: 106 s               
...omitted lines....
103/106 - feature_help.py passed, Duration: 0 s
104/106 - feature_config_args.py passed, Duration: 3 s
105/106 - rpc_help.py passed, Duration: 2 s
106/106 - p2p_node_network_limited.py passed, Duration: 10 s

@MarcoFalke Would be good to get your thoughts here.

utACK f9d138d9a79f32106895f0d1be1b25d6bf914bcf

Tested ACK 96c509e4d0a0c6d5c472f021315c0380cfd10100