Subject: bug#72536: closed (Re: [PATCH v3] tap: new `--stderr-prefix' option to prefix test script's stderr)

From: [email-masked] (GNU bug Tracking System)
Date: Sun, 23 Feb 2025 18:01:02 +0000

Your bug report

#72536: [PATCH] tap: new `--merge-prefix' option to prefix stderr before merging

which was filed against the automake-patches package, has been closed.

The explanation is attached below, along with your original report.
If you require more details, please reply to [email-masked].

-- 
72536: https://debbugs.gnu.org/cgi/bugreport.cgi?bug=72536
GNU Bug Tracking System
Contact [email-masked] with problems

Subject: Re: [PATCH v3] tap: new `--stderr-prefix' option to prefix test script's stderr
From: Karl Berry <[email-masked]>
To: [email-masked], [email-masked]
Date: Sun, 23 Feb 2025 10:59:32 -0700
List-Id: <debbugs-submit.debbugs.gnu.org>

Hi Richard - here's my tinkering with the description in the manual
(pushed).  Let me know if you see any problems.

Meanwhile, I guess we can close this. If anything more is pending from
your side, let me know or feel free to re-open. Thanks again. -k

-----------------------------------------------------------------------------
doc: move most --stderr-prefix doc to a new subsubsection.

Still in https://bugs.gnu.org/72536.

* doc/automake.texi (TAP setup and examples):
(TAP stderr examples),
TAP stderr prefixing): split TAP examples
into new subsubsections. Add discussion of race condition and
other reordering from the open bug.
* NEWS: mention --stderr-prefix.
diff --git a/NEWS b/NEWS
index 34876f3db..26b433314 100644
--- a/NEWS
+++ b/NEWS
@@ -6,6 +6,9 @@ New in 1.x:

 * New features added

+  - New option --stderr-prefix for tap-driver.sh, to prefix each line of
+    stderr from a test script with a given string. (bug#72536)
+
   - Support for Algol 68 added, based on the GNU Algol 68 compiler. (bug#75807)

   - New option dist-bzip3 for bzip3 compression of distributions. (bug#73795)
@@ -18,6 +21,9 @@ New in 1.x:
   - Avoid Perl 5.41.8+ precedence warning for use of !!.
     (https://lists.gnu.org/archive/html/automake/2025-01/msg00000.html)

+  - a Perl path containing whitespace now emits a warning instead of
+    an error, so ./configure PERL='/usr/bin/env perl' can work. (bug#74453)
+
   - The py-compile script once again does nothing (successfully) if the
     PYTHON environment variable is set to ":", or anything that isn't a
     Python interpreter (according to $PYTHON -V). Exception: if PYTHON
diff --git a/doc/automake.texi b/doc/automake.texi
index 9fa94689f..bb66aea5c 100644
--- a/doc/automake.texi
+++ b/doc/automake.texi
@@ -10516,6 +10516,7 @@ with the @samp{#} character) in the testsuite progress output too; by
 default, TAP diagnostics are only copied to the @file{.log} file.
 @item --no-comments
 Revert the effects of @option{--comments}.
+
 @item --merge
 Instruct the test driver to merge the test scripts' standard error into
 their standard output.  This is necessary if you want to ensure that
@@ -10526,8 +10527,10 @@ tracing active).  As a downside, this option might cause the test
 harness to get confused if anything that appears on standard error
 looks like a test result.  Use @option{--stderr-prefix} to prefix each
 line of standard error to avoid this problem.
+
 @item --no-merge
 Revert the effects of @option{--merge}.
+
 @item --stderr-prefix @var{STRING}
 Prefix each line of the test script's standard error with
 @code{@var{STRING}}.  Defaults to the empty string.  This option makes
@@ -10549,39 +10552,13 @@ literal characters @samp{@@%:@@} in the prefix (@samp{@@%@@&t@@:@@}, for
 example).
 @end table

-For example, in shell, @samp{--stderr-prefix "@@%:@@[stderr] "} will
-prefix each line of the test script's standard error with
-@samp{#[stderr] }.
-
-When prefixing standard error lines, the test program's standard error
-lines can be processed out of order relative to the test program's
-standard output lines, even when @option{--merge} is used.  This can be
-due to many factors, including:
-
-@itemize @bullet
-@item
-Output buffering in the test program: The test program might be
-accumulating output data and writing it to the operating system in
-batches, not as soon as it is available.  You can try
-@uref{man:setvbuf(3),,setvbuf(3)} to change the buffering mode in the
-test program, or you can add regular flushes.  OS-specific utilities to
-control buffering may be available, such as
-@uref{man:stdbuf(1),,stdbuf(1)} on GNU/Linux systems.
+For example, the option @samp{--stderr-prefix "@@%:@@[stderr] "}
+passed on the command line will prefix each line of the test script's
+standard error with @samp{#[stderr] }.

-@item
-Concurrent processing of standard output and standard error: Due to a
-limitation of the shell command language, the TAP driver processes
-standard output in a different thread or process than standard error.
-Thus, processing order is influenced by how the operating system
-schedules the two threads or processes for execution.
-
-@item
-Line-based processing: When prefixing standard error, the TAP driver
-waits until a complete line is read from the test program before
-processing the line.  This reduces the chances that characters from a
-standard output line are mixed with characters from a standard error
-line.
-@end itemize
+For more details on @option{--stderr-prefix} processing, especially
+the occasional output reordering due to a race condition, @pxref{TAP
+prefixing stderr}.

 @item --diagnostic-string @var{STRING}
 Change the string that introduces TAP diagnostics from the default value
@@ -10596,7 +10573,18 @@ the ``official'' TAP protocol does not allow for such a customization; so
 don't use it if you can avoid it.
 @end table

-@noindent
+@menu
+* TAP setup and examples:: Setup and examples of TAP usage.
+* TAP stderr examples::    Examples of stderr issues and processing.
+* TAP prefixing stderr::   Details about @option{--stderr-prefix} processing.
+@end menu
+
+@node TAP setup and examples
+@subsubsection TAP setup and examples
+
+@cindex TAP setup, example of
+@cindex setting up TAP, example
+
 Here is an example of how the TAP driver can be set up and used.

 @c Keep in sync with tap-doc2.sh
@@ -10670,7 +10658,19 @@ PASS: baz.test 1
 ...
 % @kbd{echo exit status: $?}
 exit status: 0
+@end example

+@node TAP stderr examples
+@subsubsection TAP stderr examples
+
+@cindex TAP stderr example
+@cindex stderr example in TAP
+
+Here is a sequence of examples showing the issue with merging stdout
+and stderr, and the resolution with @option{--stderr-prefix}.  Read
+the comments for specifics.
+
+@example
 % @kbd{cat stderr-demo.test}
 #!/bin/sh
 echo 'ok 1'
@@ -10721,9 +10721,69 @@ PASS: stderr-demo.test 1
 ok 2
 PASS: stderr-demo.test 2
 1..2
-
 @end example

+@node TAP prefixing stderr
+@subsubsection TAP prefixing stderr
+
+@cindex TAP prefixing stderr
+@cindex prefixing stderr in TAP
+@cindex stderr prefixing in TAP
+@cindex race condition in stderr prefixing
+
+@c see https://bugs.gnu.org/72536 for this feature and discussion.
+
+When using the above @option{--stderr-prefix} TAP option, the test
+program's standard error lines might occasionally be processed out of
+order relative to the test program's standard output lines,
+particularly when @option{--merge} is also used.  This can be due to
+many factors, including:
+
+@itemize @bullet
+@item
+Output buffering in the test program: The test program might be
+accumulating output data and writing it to the operating system in
+batches, not as soon as it is available.  You can try setvbuf(3) to
+change the buffering mode in the test program, or you can add regular
+flushes.  OS-specific utilities to control buffering may be available,
+such as stdbuf(1) on GNU/Linux systems.
+
+@item
+Concurrent processing of standard output and standard error: Due to a
+limitation of the shell command language, the TAP driver processes
+standard output in a different thread or process than standard error,
+causing a race condition.  Thus, processing order is influenced by how
+the operating system schedules the two threads or processes for
+execution.
+
+@item
+Line-based processing: When prefixing standard error, the TAP driver
+waits until a complete line is read from the test program before
+processing the line.  This reduces the chances that characters from a
+standard output line are mixed with characters from a standard error
+line.
+@end itemize
+
+Thus, stderr lines might appear out of order relative to stdout lines,
+even when @option{--merge} is passed.  All stderr lines are still
+processed in order relative to other stderr lines, and the same goes
+for the stdout lines relative to other stdout lines.  So the
+reordering shouldn't break a package's TAP tests, since there's no
+reason to output TAP commands to stderr; even more so when stderr
+lines are prefixed.
+
+When working on a particular test, if you find the reordering is
+causing trouble, you can omit @option{--stderr-prefix}, or run the
+test directly (not via TAP) to get a more accurate understanding of
+output timing.
+
+Overall, though, the order of processing (and logging) should not
+differ from the order of the test program's write(2) calls by much.
+Out-of-order processing only happens if the test program writes to
+stdout then stderr but the kernel wakes up the TAP driver's
+thread/process that is reading stderr before it wakes up the TAP
+driver's thread/process that is reading stdout, or vice versa.
+
 @node Incompatibility with other TAP parsers and drivers
 @subsection Incompatibility with other TAP parsers and drivers

compile finished at Sun Feb 23 09:55:43 2025

Subject: [PATCH] tap: new `--merge-prefix' option to prefix stderr before merging
From: Richard Hansen <[email-masked]>
To: [email-masked]
Date: Fri, 9 Aug 2024 04:38:48 -0400
List-Id: <debbugs-submit.debbugs.gnu.org>

Attached are a couple of patches to improve the TAP driver.  I don't know if `--merge-prefix' is the best name for the new option; suggestions for alternatives would be appreciated.

Thanks,
Richard

[PATCH 1/2] tap: new `--merge-prefix' option to prefix stderr before merging

* lib/tap-driver.sh: Add a new `--merge-prefix' option to direct the TAP
driver to prefix each line of the test script's standard error with the given
string before merging it with the test script's standard output.  This is
useful when standard error lines might be confused with test results.
* doc/automake.texi: Document the new `--merge-prefix' option.
* t/tap-merge-prefix.sh: New test.
* t/list-of-tests.mk (handwritten_TESTS): Add it.

[PATCH 2/2] tap: close fd 3 when invoking the test script

* lib/tap-driver.sh: Close file descriptor 3 when invoking the test script to
avoid potential conflicts with the test script.
From a8cbb5a235f89e127aef836a12e5813de112cb91 Mon Sep 17 00:00:00 2001
From: Richard Hansen <[email-masked]>
Date: Thu, 8 Aug 2024 23:34:45 -0400
Subject: [PATCH 1/2] tap: new `--merge-prefix' option to prefix stderr before
 merging

* lib/tap-driver.sh: Add a new `--merge-prefix' option to direct the TAP
driver to prefix each line of the test script's standard error with the given
string before merging it with the test script's standard output.  This is
useful when standard error lines might be confused with test results.
* doc/automake.texi: Document the new `--merge-prefix' option.
* t/tap-merge-prefix.sh: New test.
* t/list-of-tests.mk (handwritten_TESTS): Add it.
---
 doc/automake.texi     |  9 ++++++-
 lib/tap-driver.sh     | 20 ++++++++++++----
 t/list-of-tests.mk    |  1 +
 t/tap-merge-prefix.sh | 56 +++++++++++++++++++++++++++++++++++++++++++
 4 files changed, 80 insertions(+), 6 deletions(-)
 create mode 100644 t/tap-merge-prefix.sh

diff --git a/doc/automake.texi b/doc/automake.texi
index 49ebfb2b2..a1b02642c 100644
--- a/doc/automake.texi
+++ b/doc/automake.texi
@@ -10488,9 +10488,16 @@ relative to test results; this can be of great help in debugging
 (especially if your test scripts are shell scripts run with shell
 tracing active).  As a downside, this option might cause the test
 harness to get confused if anything that appears on standard error
-looks like a test result.
+looks like a test result.  Use @option{--merge-prefix} to prefix each
+line of standard error to avoid this problem.
 @item --no-merge
 Revert the effects of @option{--merge}.
+@item --merge-prefix @var{STRING}
+If @option{--merge} is in effect, prefix each line of the test script's
+standard error with @code{@var{STRING}} before merging it into standard
+output.  Typically @code{@var{STRING}} should begin with ``@code{#}'',
+which starts a TAP comment.  Defaults to the empty string.  This option
+has no effect if @option{--merge} is not in effect.
 @item --diagnostic-string @var{STRING}
 Change the string that introduces TAP diagnostics from the default value
 of ``@code{#}'' to @code{@var{STRING}}.  This can be useful if your
diff --git a/lib/tap-driver.sh b/lib/tap-driver.sh
index bd9597588..ef5057fc5 100755
--- a/lib/tap-driver.sh
+++ b/lib/tap-driver.sh
@@ -52,7 +52,8 @@ Usage:
                 [--expect-failure {yes|no}] [--color-tests {yes|no}]
                 [--enable-hard-errors {yes|no}] [--ignore-exit]
                 [--diagnostic-string STRING] [--merge|--no-merge]
-                [--comments|--no-comments] [--] TEST-COMMAND
+                [--merge-prefix STRING] [--comments|--no-comments]
+                [--] TEST-COMMAND
 The '--test-name', '-log-file' and '--trs-file' options are mandatory.
 
 Report bugs to <[email-masked]>.
@@ -69,6 +70,7 @@ trs_file=  # Where to save the metadata of the test run.
 expect_failure=0
 color_tests=0
 merge=0
+merge_prefix=
 ignore_exit=0
 comments=0
 diag_string='#'
@@ -84,6 +86,7 @@ while test $# -gt 0; do
   --enable-hard-errors) shift;; # No-op.
   --merge) merge=1;;
   --no-merge) merge=0;;
+  --merge-prefix) merge_prefix=$2; shift;;
   --ignore-exit) ignore_exit=1;;
   --comments) comments=1;;
   --no-comments) comments=0;;
@@ -140,12 +143,19 @@ fi
     # <http://mail.opensolaris.org/pipermail/ksh93-integration-discuss/2009-February/004121.html>
     trap : 1 3 2 13 15
     if test $merge -gt 0; then
-      exec 2>&1
+      exec 4>&1
+      # A shell `while' loop is used to read and prefix the stderr
+      # lines instead of `awk' because `mawk' aggressively buffers its
+      # input (except with the `-Winteractive' command-line option),
+      # which defeats the purpose of merging the output.
+      { "$@"; echo $?; } 2>&1 >&4 4>&- | while IFS= read -r line; do
+        printf %s\\n "$merge_prefix$line"
+      done
+      exec 4>&-
     else
-      exec 2>&3
+      "$@" 2>&3
+      echo $?
     fi
-    "$@"
-    echo $?
   ) | LC_ALL=C ${AM_TAP_AWK-awk} \
         -v me="$me" \
         -v test_script_name="$test_name" \
diff --git a/t/list-of-tests.mk b/t/list-of-tests.mk
index e80ace470..ad8976738 100644
--- a/t/list-of-tests.mk
+++ b/t/list-of-tests.mk
@@ -1153,6 +1153,7 @@ t/tap-msg0-directive.sh \
 t/tap-msg0-planskip.sh \
 t/tap-msg0-bailout.sh \
 t/tap-msg0-misc.sh \
+t/tap-merge-prefix.sh \
 t/tap-merge-stdout-stderr.sh \
 t/tap-no-merge-stdout-stderr.sh \
 t/tap-no-disable-hard-error.sh \
diff --git a/t/tap-merge-prefix.sh b/t/tap-merge-prefix.sh
new file mode 100644
index 000000000..0ed0929b6
--- /dev/null
+++ b/t/tap-merge-prefix.sh
@@ -0,0 +1,56 @@
+#! /bin/sh
+# Copyright (C) 2024 Free Software Foundation, Inc.
+#
+# This program is free software; you can redistribute it and/or modify
+# it under the terms of the GNU General Public License as published by
+# the Free Software Foundation; either version 2, or (at your option)
+# any later version.
+#
+# This program is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+# GNU General Public License for more details.
+#
+# You should have received a copy of the GNU General Public License
+# along with this program.  If not, see <https://www.gnu.org/licenses/>.
+
+# TAP support:
+#  - The Automake TAP driver has an option that instructs it to prefix stderr
+#    with a given string before merging it with stdout.
+
+. test-init.sh
+
+fetch_tap_driver
+
+# There's apparently no portable way to escape # in a make variable, so use
+# printf with an octal escape for the character's representation.  We could
+# just $(printf '\043'), but that doesn't work on EBCDIC systems so the octal
+# representation is computed here.
+octothorpe_octal=$(printf %03o "'#")
+cat > Makefile.am <<END
+AM_TEST_LOG_DRIVER_FLAGS = --merge \\
+	--merge-prefix "\$\$(printf '\\$octothorpe_octal')<stderr> "
+TESTS = all.test
+END
+
+cat Makefile.am  # for debugging
+
+. tap-setup.sh
+
+cat > all.test <<END
+#!/bin/sh
+echo 1..2
+echo ok 1
+echo 'Bail out!' >&2
+echo ok 2
+END
+chmod a+x all.test
+
+run_make -O check
+count_test_results total=2 pass=2 fail=0 xpass=0 xfail=0 skip=0 error=0
+
+cat all.log  # for debugging
+
+grep -e '^#<stderr> Bail out!$' all.log
+
+:
-- 
2.40.1

From 7414e7fc942512e4c8084fbee7515488b3a3e2e5 Mon Sep 17 00:00:00 2001
From: Richard Hansen <[email-masked]>
Date: Thu, 8 Aug 2024 23:41:40 -0400
Subject: [PATCH 2/2] tap: close fd 3 when invoking the test script

* lib/tap-driver.sh: Close file descriptor 3 when invoking the test script to
avoid potential conflicts with the test script.
---
 lib/tap-driver.sh | 6 ++----
 1 file changed, 2 insertions(+), 4 deletions(-)

diff --git a/lib/tap-driver.sh b/lib/tap-driver.sh
index ef5057fc5..8a59b423b 100755
--- a/lib/tap-driver.sh
+++ b/lib/tap-driver.sh
@@ -148,12 +148,12 @@ fi
       # lines instead of `awk' because `mawk' aggressively buffers its
       # input (except with the `-Winteractive' command-line option),
       # which defeats the purpose of merging the output.
-      { "$@"; echo $?; } 2>&1 >&4 4>&- | while IFS= read -r line; do
+      { "$@"; echo $?; } 2>&1 >&4 3>&- 4>&- | while IFS= read -r line; do
         printf %s\\n "$merge_prefix$line"
       done
       exec 4>&-
     else
-      "$@" 2>&3
+      "$@" 2>&3 3>&-
       echo $?
     fi
   ) | LC_ALL=C ${AM_TAP_AWK-awk} \
@@ -648,8 +648,6 @@ exit 0
 
 } # End of "BEGIN" block.
 '
-
-# TODO: document that we consume the file descriptor 3 :-(
 } 3>"$log_file"
 
 test $? -eq 0 || fatal "I/O or internal error"
-- 
2.40.1