Flux-core: testsuite: failures when run with `debug=t` OR `verbose=t`

[SteVwonder]

From the bionic docker image:

$ make check
...
============================================================================
Testsuite summary for flux-core 0.21.0-109-ge951673df
============================================================================
# TOTAL: 2898
# PASS:  2858
# SKIP:  37
# XFAIL: 3
# FAIL:  0
# XPASS: 0
# ERROR: 0
============================================================================

$ verbose=t debug=t make check
...
============================================================================
Testsuite summary for flux-core 0.21.0-109-ge951673df
============================================================================
# TOTAL: 3571
# PASS:  2657
# SKIP:  36
# XFAIL: 3
# FAIL:  15
# XPASS: 0
# ERROR: 860
============================================================================

The list of failed tests:

❯ grep -oE "^FAIL: [^ ]+" test-suite.log | uniq -c                                                                                                                                                                             16:40:50 ()
  14 FAIL: t0000-sharness.t
   1 FAIL: t0001-basic.t

❯ grep -oE "^ERROR: [^ ]+" test-suite.log | sort | uniq -c                                                                                                                                                                     16:40:57 ()
   1 ERROR: t0000-sharness
   1 ERROR: t0000-sharness.t
   1 ERROR: t0001-basic
   1 ERROR: t0001-basic.t
   1 ERROR: t2230-job-info-list
  25 ERROR: t2230-job-info-list.t
   1 ERROR: t2313-resource-acquire
   9 ERROR: t2313-resource-acquire.t
   1 ERROR: t2603-job-shell-influx-shell:
   1 ERROR: t2603-job-shell-initrc
 670 ERROR: t2603-job-shell-initrc.t
   1 ERROR: t2608-job-shell-log
 153 ERROR: t2608-job-shell-log.t

[grondo]

I wonder if the debug output is just causing invalid TAP output to be emitted due to the extra output.
E.g. this works:

$ debug=t verbose=t ./t2603-job-shell-initrc.t

since it is the same as

$ ./t2603-job-shell-initrc.t -d -v

Though the t0000-sharness.t sharness tests still fail (probably because sharness-in-sharness isn't expected to have debug/verbose mode inherited)

Are you just trying to get debug output from all tests? Then you can use

 $  debug=t FLUX_TESTS_LOGFILE=t make -j 16 check 

If it seems that verbose=t and TAP output isn't necessarily compatible, but FLUX_TESTS_LOGFILE=t enables --logfile for all tests and the verbose+debug output will be placed into .output, instead of going to stdout and being captured by the TAP harness. (This is what we do in travis-ci)

[grondo]

Oh, the above does require this patch for t0000-sharness.t:

diff --git a/t/t0000-sharness.t b/t/t0000-sharness.t
index b476ba41d..7a4dbaa28 100755
--- a/t/t0000-sharness.t
+++ b/t/t0000-sharness.t
@@ -64,6 +64,8 @@ run_sub_test_lib_test () {
                cat >>".$name.t" &&
                chmod +x ".$name.t" &&
                export SHARNESS_TEST_SRCDIR &&
+               unset verbose &&
+               unset debug &&
                $prefix ./".$name.t" $opt --chain-lint >out 2>err
        )
 }
@@ -333,6 +335,8 @@ test_expect_success 'tests can be run from an alternate directory' '
          unset SHARNESS_TEST_DIRECTORY SHARNESS_TEST_SRCDIR &&
          # unset HARNESS_ACTIVE so we get a test-results dir
          unset HARNESS_ACTIVE &&
+         unset debug &&
+         unset verbose &&
          chmod +x test.t &&
          mkdir test-rundir &&
          cd test-rundir &&
@@ -423,6 +427,8 @@ test_expect_success 'loading sharness extensions works' '
                EOF
                unset SHARNESS_TEST_DIRECTORY SHARNESS_TEST_SRCDIR &&
                chmod +x ./test-extension.t &&
+               unset debug &&
+               unset verbose &&
                ./test-extension.t >out 2>err &&
                cat >expected <<-\EOF &&
                ok 1 - extension function is present
@@ -452,6 +458,8 @@ test_expect_success 'empty sharness.d directory does not cause failure' '
                EOF
                unset SHARNESS_TEST_DIRECTORY SHARNESS_TEST_SRCDIR &&
                chmod +x ./test.t &&
+               unset verbose &&
+               unset debug &&
                ./test.t >out 2>err &&
                cat >expected <<-\EOF &&
                ok 1 - test success

[SteVwonder]

Are you just trying to get debug output from all tests? Then you can use
$ debug=t FLUX_TESTS_LOGFILE=t make -j 16 check

Perfect! Yeah, that was exactly what I was trying to do. That combined with the t0000-sharness fix is exactly what I was looking for! I'll give that a shot.

[SteVwonder]

That seems to mostly have done the trick. There is still one subtest failing:

PASS: t4000-issues-test-driver.t 1 - t0441-kvs-put-get.sh
PASS: t4000-issues-test-driver.t 2 - t0505-msg-handler-reg.lua
PASS: t4000-issues-test-driver.t 3 - t0821-kvs-segfault.sh
PASS: t4000-issues-test-driver.t 4 - t1760-kvs-use-after-free.sh
PASS: t4000-issues-test-driver.t 5 - t1876-kvs-watch-cancel-race.sh
PASS: t4000-issues-test-driver.t 6 - t2281-service-add-crash.sh
PASS: t4000-issues-test-driver.t 7 - t2284-initial-program-format-chars.sh
PASS: t4000-issues-test-driver.t 8 - t2337-loop-closes-stdin.sh
FAIL: t4000-issues-test-driver.t 9 - t2686-shell-input-race.sh
PASS: t4000-issues-test-driver.t 10 - t2711-rpc-in-aux-item-destructor.sh
PASS: t4000-issues-test-driver.t 11 - t3186-python-future-get-sigint.sh
ERROR: t4000-issues-test-driver.t - exited with status 1

t4000-issues-test-driver.output:

expecting success: run_timeout 30 /usr/src/t/issues/t2686-shell-input-race.sh
{"version": 1, "execution": {"R_lite": [{"rank": "0-3", "children": {"core": "0-15"}}], "starttime": 0.0, "expiration": 0.0, "nodelist": ["docker-desktop,docker-desktop,docker-desktop,docker-desktop"]}}
2020-11-22T23:05:52.334371Z sched-simple.debug[0]: ready: 64 of 64 cores: rank[0-3]/core[0-15]
172251676672
172251676673
172251676674
172251676675
172251676676
172251676677
172268453888
172268453889
172268453890
172268453891
172268453892
172268453893
172285231104
172285231105
172285231106
172285231107
172302008320
172302008321
172302008322
172302008323
172302008324
172318785536
172318785537
172318785538
not ok 9 - t2686-shell-input-race.sh

I'm not sure why it failed since I don't see any job ID or guestlog outputs. So I assume RC=0.

Either way, the path above is exactly what I need for flux-accounting. Thanks @grondo!

[grondo]

I have seen that test fail even during normal test runs, I wonder if the test itself is fragile.