Print a completion message when all tests are done

[nickrobinson251]

To make it clear when tests are done (in case there's a problem after this point but before we print a test summary).

This is mainly helpful when running with multiple workers, as in that case the last test to finish and print a DONE log may not be the last test-item started, i.e. the final log before all tests are done may be `DONE (33/37) test item ...".

Also adds more @debug logs, for helping diagnose issues after tests are all run.

Before:

julia> runtests("test/testfiles/_happy_tests.jl", nworkers=2)
  Activating project at `~/repos/ReTestItems.jl`
[ Info: Scanning for test items in project `ReTestItems` at paths: test/testfiles/_happy_tests.jl
[ Info: Finished scanning for test items in 0.67 seconds. Scheduling 3 tests on pid 71250 with 2 worker processes and 2 threads per worker.
[ Info: Starting test workers
  Worker 71406:  [ Info: Starting test worker 1 on pid = 71406, with 2 threads
  Worker 71405:  [ Info: Starting test worker 2 on pid = 71405, with 2 threads
[ Info: Starting running test items
  Worker 71406:  12:53:53 | START (1/3) test item "happy 1" at test/testfiles/_happy_tests.jl:1
  Worker 71405:  12:53:53 | START (2/3) test item "happy 2" at test/testfiles/_happy_tests.jl:5
  Worker 71405:  12:53:53 | DONE  (2/3) test item "happy 2" <0.1 secs (90.8% compile), 17.24 K allocs (1.255 MB)
  Worker 71406:  12:53:53 | DONE  (1/3) test item "happy 1" <0.1 secs (91.0% compile), 17.24 K allocs (1.255 MB)
  Worker 71405:  12:53:53 | START (3/3) test item "happy 3" at test/testfiles/_happy_tests.jl:9
  Worker 71405:  12:53:53 | DONE  (3/3) test item "happy 3" <0.1 secs (<0.1% compile), 1.62 K allocs (116.776 KB)
Test Summary:                        | Pass  Total  Time
ReTestItems                          |    3      3  3.2s
  test                               |    3      3
    test/testfiles                   |    3      3
      test/testfiles/_happy_tests.jl |    3      3
        happy 1                      |    1      1  0.0s
        happy 2                      |    1      1  0.0s
        happy 3                      |    1      1  0.0s

Now:

julia> runtests("test/testfiles/_happy_tests.jl", nworkers=2)
  Activating project at `~/repos/ReTestItems.jl`
[ Info: Scanning for test items in project `ReTestItems` at paths: test/testfiles/_happy_tests.jl
[ Info: Finished scanning for test items in 0.67 seconds. Scheduling 3 tests on pid 66797 with 2 worker processes and 2 threads per worker.
[ Info: Starting test workers
  Worker 67159:  [ Info: Starting test worker 2 on pid = 67159, with 2 threads
  Worker 67160:  [ Info: Starting test worker 1 on pid = 67160, with 2 threads
[ Info: Starting running test items
  Worker 67160:  14:27:23 | START (1/3) test item "happy 1" at test/testfiles/_happy_tests.jl:1
  Worker 67159:  14:27:23 | START (2/3) test item "happy 2" at test/testfiles/_happy_tests.jl:5
  Worker 67160:  14:27:23 | DONE  (1/3) test item "happy 1" <0.1 secs (91.5% compile), 17.24 K allocs (1.255 MB)
  Worker 67159:  14:27:23 | DONE  (2/3) test item "happy 2" <0.1 secs (91.1% compile), 17.24 K allocs (1.255 MB)
  Worker 67160:  14:27:23 | START (3/3) test item "happy 3" at test/testfiles/_happy_tests.jl:9
[ Info: All tests on worker 2 completed. Closing Worker(pid=67159).
  Worker 67160:  14:27:23 | DONE  (3/3) test item "happy 3" <0.1 secs (<0.1% compile), 1.62 K allocs (116.776 KB)
[ Info: All tests on worker 1 completed. Closing Worker(pid=67160).
[ Tests Completed: 3/3 test items were run.
Test Summary:                        | Pass  Total  Time
ReTestItems                          |    3      3  3.1s
  test                               |    3      3
    test/testfiles                   |    3      3
      test/testfiles/_happy_tests.jl |    3      3
        happy 1                      |    1      1  0.0s
        happy 2                      |    1      1  0.0s
        happy 3                      |    1      1  0.0s

[Drvi]

Before I look at the changes here, I wanted to point out that you were right that we're waiting for the workers to terminate -- the @sync block where we @spawn each of the manage-workers tasks will block since we're closing them which waits for the tasks on the worker to finish (in response to it being terminated). This place does feel like a good spot for the hang to happen to me... Maybe we could use a timedwait instead of wait to be on the safer side?

[NHDaly]

ah, so @Drvi this would be maybe too late already, since we hang before shutting down the workers?

Maybe we actually just want a log in manage_worker, here?:

ReTestItems.jl/src/ReTestItems.jl

Line 695 in e9b7730

close(worker)

We could basically say

@info "Finished all tests. Closing Worker $workerid."

?

[nickrobinson251]

Added. I just added a log for each worker, so they don't have to coordinate to know if they're the last worker to complete, and also because i support any of them could be the one to hang here.