tests: show the progress of functional tests

[isghe]

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

[promag]

nit, test_count = len(test_list)

[isghe]

done

[practicalswift]

Concept ACK

[kristapsk]

ACK 90829116645690c2c8b668ecc4ef117897dcb571

[promag]

utACK 9082911.

[meshcollider]

utACK 9082911

You should probably squash the commits though

[laanwj]

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.)

[laanwj]

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."""

[practicalswift]

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 :-)

[isghe]

@laanwj I tried to show the spinner, but the effect was a boring user experience, not seeing the progress of the current functional test isghe@4a41f8e

So now the dots are shown only for the current test in progress, "deleting" the line of dots from the previous test 2b3c35c:

$ 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 cc9c616

[fanquake]

@isghe please squash your commits

[isghe]

@fanquake squashed

[fanquake]

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.

[maflcko]

The %s/%s - %s%s%s part is always the same. Could move it out of the branches?

done_str = "{}/{} - {}{}{}".format(i+1,test_count,BOLD...

[isghe]

done and squashed

[maflcko]

utACK f9d138d9a79f32106895f0d1be1b25d6bf914bcf

[conscott]

Tested ACK 96c509e