--show-output-of-passing-tests does show no run $output on passing tests

[jgehrcke]

Thank you for the great work on this important project.

Summary

I have seen output (stdout + stderr) not being captured and outputted as expected for passing tests when using --show-output-of-passing-tests. The problem is reflected in the temp dir where captured output is supposed to reside in the files stdout and stderr which are for passing tests unexpectedly empty. --print-output-on-failure seems to largely work, but may store stderr as stdout.

--gather-test-outputs-in <directory> in my case generates empty files, but I suppose this is the same problem as with --show-output-of-passing-tests in my case, so let's focus on that.

Something might be special about my environment, but I think it's not too special.

Detail

Repro (a little big, but it's what I have for now):

cd /tmp
mkdir repro && cd repro
git clone https://github.com/jgehrcke/github-repo-stats
cd github-repo-stats
make clitests # yes this takes a while as it builds images

This should lead to a passing test suite. Output for me:

1..9
ok 1 analyze.py: snapshots: some, vcagg: yes, stars: some, forks: none in 2150ms
...
ok 9 analyze.py: snapshots: some, vcagg: no, stars: none, forks: some, starsnaps: yes in 1807ms
BATS_RUN_TMPDIR: /tmp/bats-run-0H7qBH

Now edit Makefile and change:

                -c "cd /cwd && bats \
-                       --print-output-on-failure \
+                       --show-output-of-passing-tests \
                        --no-tempdir-cleanup \
-                       --timing \
-                       --jobs 5 \
                        tests/*.bats \

(the removals are for keeping things simple).

Run make clitests again. The test suite still passes, but the expected output is not emitted, the bats output does (on my machine) not change compared to not providing --show-output-of-passing-tests.

Yes, this runs bats in a container, and it mounts the host /tmp into the container /tmp. I hope this is nothing too concerning.

By inspecting the tmp dir after the test run we can see that the output indeed wasn't captured properly:

$ pwd
/tmp/bats-run-0H7qBH/parallel_output/1
$ ls
total 8.0K
4.0K pid     0 stderr  4.0K stdout
$ cat stdout 
ok 1 analyze.py: snapshots: some, vcagg: yes, stars: some, forks: none in 2150ms

Expected: in this case I expect stderr to be filled with log statements (Python's default logging behavior: writes to stderr), and stdout would be expected to be empty (the tested program does not write to stdout).

Observed: stderr is empty (unexpected) and stdout contains output from the bats test runner (that seems to be fine. too). That is, stderr of the tested program is 'lost'. However, that's not specific to stderr. I tried emitting on stdout, too, it's then also not captured (not appearing in the stdout file).

What's interesting is that in this very setup --print-output-on-failure seems to work almost fine for me: in case of a failure, the output is generally captured and printed.

That is, output capturing is not generally broken in my case, but there seems to be an asymmetry between --print-output-on-failure and --show-output-of-passing-tests.

Peculiarity with --print-output-on-failure when looking in more detail: stderr is captured as stdout:

$ pwd
/tmp/bats-run-InrVrF/parallel_output/9
$ cat stdout 
not ok 9 analyze.py: snapshots: some, vcagg: no, stars: none, forks: some, starsnaps: yes in 1111ms
# (in test file tests/analyze.bats, line 140)
#   `[ "$status" -eq 0 ]' failed
# Last output:
# 231001-13:12:38.238 INFO: Create output directory: /tmp/bats-run-InrVrF/test/9/outdir
<snip>
# msg emitted to stderr

That last bit is generated by sys.exit("msg emitted to stderr") in Python which writes to stderr. The stderr file as created by bats is empty:

$ cat stderr | wc
      0       0       0

(as expected, kind of, because this seems to to have been redirected to the file called stdout; but that redirection itself is at least unexpected to me).

Environment (please complete the following information):

• Bats version v1.10.0 checkout

As this is a containerized setup you can see how it's created. For a quick overview I have added cat /etc/*-release && bash --version to the cmd run in the container right before invoking bats:

PRETTY_NAME="Debian GNU/Linux 10 (buster)"
NAME="Debian GNU/Linux"
...
GNU bash, version 5.0.3(1)-release (x86_64-pc-linux-gnu)

Additional context

I rarely get a race condition hitting in while executing this test suite, where a mv/rename after creating a file doesn't reliably work:

#   File "/cwd/analyze.py", line 86, in main
#     df_stargazers = process_stargazer_input()
#   File "/cwd/analyze.py", line 1587, in process_stargazer_input
#     os.rename(tpath, ARGS.stargazer_ts_resampled_outpath)
# FileNotFoundError: [Errno 2] No such file or directory: 'stargazers-rs.csv.tmp' -> 'stargazers-rs.csv'

If you get this, please re-run. I sincerely do hope this is an independent issue (whereas I fear this is some tmpfs magic doing terrible things).

[martin-schulze-vireso]

I think this is working as intended but badly documented. Note the difference in wording between --print-output-on-failure and --show-output-of-passing-tests (print vs show) and the ambiguity of output. In the first case it is not clear which output is referred to, in the second case it is the test's output.

To clarify what is happening: When using --print-output-on-failure, the contents of $output are printed and gathered as test outputs. When the test fails, the formatter will receive all outputs of the test to show the user.

This is where --show-output-of-passing-tests comes into play: Even when the test passed, the output will be forwarded. Alas, --print-output-on-failure won't do any printing without a failure, so there is nothing to show. You can mitigate this by adding --verbose-run which makes run always print its output. (Leading to a duplication of $output when using that together with --print-output-on-failure).

So as I said above, this requires better documentation to manage expectations.