Re: [PATCH 2/3] test-lib: add --verbose-log option

[Jeff King]

On Fri, Oct 21, 2016 at 10:12:16AM -0700, Junio C Hamano wrote:

> > -if test "$verbose" = "t"
> > +if test "$verbose_log" = "t"
> > +then
> > +   exec 3>>"$GIT_TEST_TEE_OUTPUT_FILE" 4>&3
> > +elif test "$verbose" = "t"
> >  then
> > exec 4>&2 3>&1
> >  else
> 
> OK, unlike "verbose" case where we give 3 (saved stdout) to 1 and 4
> (saved stderr) to 2, we send 3 to the output file and 4 to the same.

Your comment made me double-check whether we ought to be separating the
two in any way. Because my statement earlier in the thread that the
--verbose output goes to stdout is not _entirely_ true. It goes to
stdout and stderr, as written by the various programs in the tests.

So:

  ./t-whatever.sh -v | less

isn't quite sufficient. You really do want "2>&1" in there to catch
everything.

But for the case of "--tee", we already do so, in order to make sure it
all goes to the logfile. And since this option always implies "--tee",
it is correct here to send "3" and "4" to the same place.

So the patch is correct. But when I said earlier that people might be
annoyed if we just sent --verbose output to stderr, that probably isn't
true. We could perhaps make:

  prove t-whatever.sh :: -v

"just work" by sending all of the verbose output to stderr. I don't
think it really matters, though. Nobody is doing that, because it's
pointless without "--tee".

-Peff

Re: [PATCH 2/3] test-lib: add --verbose-log option

[Junio C Hamano]

Jeff King  writes:

> This patch implements option (5), which seems to work well
> in practice.

Your journey to reach this final design and implementation may have
been painful---I really like the end result.  This was an accident
waiting to happen.

Thanks for fixing it.

> @@ -319,7 +332,10 @@ fi
>  
>  exec 5>&1
>  exec 6<&0
> -if test "$verbose" = "t"
> +if test "$verbose_log" = "t"
> +then
> + exec 3>>"$GIT_TEST_TEE_OUTPUT_FILE" 4>&3
> +elif test "$verbose" = "t"
>  then
>   exec 4>&2 3>&1
>  else

OK, unlike "verbose" case where we give 3 (saved stdout) to 1 and 4
(saved stderr) to 2, we send 3 to the output file and 4 to the same.

Makes sense.

[PATCH 2/3] test-lib: add --verbose-log option

[Jeff King]

The "--verbose" option redirects output from arbitrary
test commands to stdout. This is useful for examining the
output manually, like:

  ./t5547-push-quarantine.sh -v | less

But it also means that the output is intermingled with the
TAP directives, which can confuse a TAP parser like "prove".
This has always been a potential problem, but became an
issue recently when one test happened to output the word
"ok" on a line by itself, which prove interprets as a test
success:

  $ prove t5547-push-quarantine.sh :: -v
  t5547-push-quarantine.sh .. 1/? To dest.git
   * [new branch]  HEAD -> master
  To dest.git
   ! [remote rejected] reject -> reject (pre-receive hook declined)
  error: failed to push some refs to 'dest.git'
  fatal: git cat-file d08c8eba97f4e683ece08654c7c8d2ba0c03b129: bad file
  t5547-push-quarantine.sh .. Failed -1/4 subtests

  Test Summary Report
  ---
  t5547-push-quarantine.sh (Wstat: 0 Tests: 5 Failed: 0)
Parse errors: Tests out of sequence.  Found (2) but expected (3)
  Tests out of sequence.  Found (3) but expected (4)
  Tests out of sequence.  Found (4) but expected (5)
  Bad plan.  You planned 4 tests but ran 5.
  Files=1, Tests=5,  0 wallclock secs ( 0.01 usr +  0.01 sys =  0.02 CPU)
  Result: FAIL

One answer is "if it hurts, don't do it", but that's not
quite the whole story. The Travis tests use "--verbose
--tee" so that they can get the benefit of prove's parallel
options, along with a verbose log in case there is a
failure. We just need the verbose output to go to the log,
but keep stdout clean.

Getting this right turns out to be surprisingly difficult.
Here's the progression of alternatives I considered:

 1. Add an option to write verbose output to stderr. This is
hard to capture, though, because we want each test to
have its own log (because they're all run in parallel
and the jumbled output would be useless).

 2. Add an option to write verbose output to a file in
test-results. This works, but the log is missing all of
the non-verbose output, which gives context.

 3. Like (2), but teach say_color() to additionally output
to the log. This mostly works, but misses any output
that happens outside of the say() functions (which isn't
a lot, but is a potential maintenance headache).

 4. Like (2), but make the log file the same as the "--tee"
file. That almost works, but now we have two processes
opening the same file. That gives us two separate
descriptors, each with their own idea of the current
position. They'll each start writing at offset 0, and
overwrite each other's data.

 5. Like (4), but in each case open the file for appending.
That atomically positions each write at the end of the
file.

It's possible we may still get sheared writes between
the two processes, but this is already the case when
writing to stdout. It's not a problem in practice
because the test harness generally waits for snippets to
finish before writing the TAP output.

We can ignore buffering issues with tee, because POSIX
mandates that it does not buffer. Likewise, POSIX
specifies "tee -a", so it should be available
everywhere.

This patch implements option (5), which seems to work well
in practice.

Signed-off-by: Jeff King 
---
Arguably we don't need a new option for this, and could just do it
automatically. I wasn't sure when, though:

  - if "--tee --verbose" triggers it, then somebody running that outside
of "prove" who _wants_ the verbose output on stdout (because they're
looking at it, but also want to save a copy to the log) would be
regressed

  - possibly "--tee" could just always write verbose output to the
logfile (but not stdout). That's kind of weirdly magical, and we'd
have to update the travis invocation anyway.

So I went with a new option which implies the other ones. No chance of
regression, and it's easy to explain.

 t/README  |  6 ++
 t/test-lib.sh | 22 +++---
 2 files changed, 25 insertions(+), 3 deletions(-)

diff --git a/t/README b/t/README
index 0f764c0aef..4982d1c521 100644
--- a/t/README
+++ b/t/README
@@ -153,6 +153,12 @@ appropriately before running "make".
As the names depend on the tests' file names, it is safe to
run the tests with this option in parallel.
 
+--verbose-log::
+   Write verbose output to the same logfile as `--tee`, but do
+   _not_ write it to stdout. Unlike `--tee --verbose`, this option
+   is safe to use when stdout is being consumed by a TAP parser
+   like `prove`. Implies `--tee` and `--verbose`.
+
 --with-dashes::
By default tests are run without dashed forms of
commands (like git-commit) in the PATH (it only uses
diff --git a/t/test-lib.sh b/t/test-lib.sh
index 33cbbb7806..85946ec40d 100644
--- a/t/test-lib.sh
+++ b/t/test-lib.sh
@@ -54,11 +54,21 @@ case