Subject: [PATCH] tap: followups for the new `--stderr-prefix' option

From: Richard Hansen <[email-masked]>
Date: Sun, 23 Feb 2025 20:23:15 -0500

On 2/23/25 12:53, Karl Berry wrote:
> I pushed it. Thanks!!

Thank you!  And thank you for the documentation improvements.

I have some minor follow-up commits, attached:

   1. Minor documentation revisions.
   2. Change command_ok_ to support shell functions.
   3. New test to check stdout/stderr processing order.

-Richard
From f5a83ea47e3bed44cd1f1c21eff1ed71b3afc605 Mon Sep 17 00:00:00 2001
From: Richard Hansen <[email-masked]>
Date: Sun, 23 Feb 2025 19:01:50 -0500
Subject: [PATCH 1/3] doc: Revise `--stderr-prefix' documentation

* doc/automake.texi (TAP prefixing stderr): Tweak the wording to
clarify, and mention awk input buffering.
---
 doc/automake.texi | 46 ++++++++++++++++++++++++++++------------------
 1 file changed, 28 insertions(+), 18 deletions(-)

diff --git a/doc/automake.texi b/doc/automake.texi
index b520880c5..6dcd94826 100644
--- a/doc/automake.texi
+++ b/doc/automake.texi
@@ -10741,9 +10741,11 @@ PASS: stderr-demo.test 2
 
 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:
+order relative to the test program's standard output lines, even when
+@option{--merge} is also used.  This can cause confusion when reading a
+test's log because a stdout line might appear earlier (or later) than a
+stderr line despite being output by the test program after (or before)
+the stderr line.  This reordering can be due to many factors, including:
 
 @itemize @bullet
 @item
@@ -10754,34 +10756,42 @@ 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
+Input buffering in the TAP driver: The TAP driver relies on the awk(1)
+utility, and some awk implementations (notably mawk) aggressively buffer
+their input (the test program output).  This causes stderr lines to
+appear in the test log much earlier than stdout lines.  The
+@option{--merge} option addresses this by sending the stderr lines to
+awk along with the stdout lines, rendering awk's input buffering
+irrelevant.  (This issue also applies when @option{--stderr-prefix} is
+not used.)
+
 @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.
+causing a race condition.  Processing order is influenced by how the
+operating system schedules the two threads or processes for execution,
+which is outside the TAP driver's control.
 
 @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.
+line, but it delays processing until the line terminator is encountered.
 @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.
+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.
+When troubleshooting a particular test, if you find the reordering is
+causing confusion, you can omit @option{--stderr-prefix}, or run the
+test program directly (not via the TAP driver) 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.
-- 
2.48.1

From fb21a271aa51c12935f82b8b73503ff934e4cd9c Mon Sep 17 00:00:00 2001
From: Richard Hansen <[email-masked]>
Date: Sun, 23 Feb 2025 19:21:17 -0500
Subject: [PATCH 2/3] tests: add shell function support to `command_ok_'

* t/ax/tap-functions.sh (command_ok_): Run the command without testing
the exit status with `||' in case the command is a shell function.
This avoids unintentionally disabling `set -e' inside the shell
function.
---
 t/ax/tap-functions.sh | 24 +++++++++++++++++++++++-
 1 file changed, 23 insertions(+), 1 deletion(-)

diff --git a/t/ax/tap-functions.sh b/t/ax/tap-functions.sh
index 5b36b1c87..c5dbc75f6 100644
--- a/t/ax/tap-functions.sh
+++ b/t/ax/tap-functions.sh
@@ -227,7 +227,29 @@ command_ok_ ()
     esac
     shift
   done
-  tap_result_="ok"; "$@" || tap_result_="not ok"
+  tap_result_="ok"
+  # Temporarily disable `set -e` if enabled so that the shell does not abort
+  # if the command fails.  (See the comment below for why `|| handle_error`
+  # can't be used.)  The `set +o` command could be used instead of examining
+  # `$-`, but that would add lots of `set -x` log spam.
+  case $- in
+    *e*) restore_set_e_='set -e';;
+    *) restore_set_e_='';;
+  esac
+  set +e
+  # Run the command in a subshell in case the command is a shell function that
+  # invokes `exit` (perhaps indirectly via `set -e`).  This also prevents the
+  # function from modifying the outer shell execution environment (e.g.,
+  # change variables), which may be an upside or a downside depending on what
+  # the function wants to do.
+  #
+  # Do NOT put the command or the subshell on the left-hand side of a `||` (or
+  # as the condition of an `if` statement, etc.).  Otherwise, if the command
+  # is a shell function, `set -e` would be effectively disabled inside the
+  # function, potentially causing failures to be treated as successes.
+  (eval "$restore_set_e_" && "$@")
+  test "$?" -eq 0 || tap_result_="not ok"
+  eval "$restore_set_e_"
   result_ "$tap_result_" -D "$tap_directive_" -r "$tap_reason_" \
           -- "$tap_description_"
 }
-- 
2.48.1

From ffec4f33fe2bd283f72da909befed8dd53b1c586 Mon Sep 17 00:00:00 2001
From: Richard Hansen <[email-masked]>
Date: Sun, 23 Feb 2025 19:21:23 -0500
Subject: [PATCH 3/3] tests: test TAP stdout/stderr order with --merge
 --stderr-prefix

* t/tap-stderr-prefix.tap: Add a test checking the processing order of stdout
lines relative to stderr lines when the TAP driver is passed `--merge' and
`--stderr-prefix'.
---
 t/tap-stderr-prefix.tap | 42 +++++++++++++++++++++++++++++++++++++++++
 1 file changed, 42 insertions(+)

diff --git a/t/tap-stderr-prefix.tap b/t/tap-stderr-prefix.tap
index 718988991..7f2ea2457 100644
--- a/t/tap-stderr-prefix.tap
+++ b/t/tap-stderr-prefix.tap
@@ -124,6 +124,48 @@ command_ok_ "$PFXFLAG --merge: prefixed stderr in log" -- \
 command_ok_ "$PFXFLAG --merge: missing final newline is added" -- \
     grep -q '^##@%:@ final stderr line without newline terminator$' all.log
 
+
+# Test preserved stdout/stderr ordering.  The sleeps between writes are
+# necessary because stdout and stderr are independent and thus inherently race
+# with each other.  (The kernel can wake up the two downstream reader threads
+# in the opposite order from the upstream writes.  Or, if the TAP driver was
+# changed to use select or poll, the upstream writer can write to both streams
+# before the kernel wakes up the one downstream reader.)
+PFXFLAG='--stderr-prefix "# "'
+desc="$PFXFLAG --merge stdout/stderr ordering"
+cat >all.test <<END || bailout_ "failed to create all.test"
+#!/bin/sh
+echo '1..1'
+sleep 1
+echo 'stderr 1' >&2
+sleep 1
+echo 'ok 1'
+sleep 1
+echo 'stderr 2' >&2
+END
+chmod a+x all.test || bailout_ "failed to make all.test executable"
+
+check_log_line_order() {
+  {
+    grep -xe "$1" all.log
+    grep -xe "$2" all.log
+    sed -n -e '/^\('"$1"'\)$/,${/^\('"$2"'\)$/p}' all.log | grep -xe "$2"
+  } >&2  # Write to stderr in case $1 or $2 looks like a TAP directive.
+}
+
+command_ok_ "$desc: make check passes" -- \
+  run_make -O AM_TEST_LOG_DRIVER_FLAGS="$PFXFLAG --merge" check
+dumpf all.log
+command_ok_ "$desc: result counts are correct" -- \
+  count_test_results total=1 pass=1 fail=0 xpass=0 xfail=0 skip=0 error=0
+command_ok_ "$desc: '1..1' before 'stderr 1'" -- \
+  check_log_line_order '1\.\.1' '# stderr 1'
+command_ok_ "$desc: 'stderr 1' before 'ok 1'" -- \
+  check_log_line_order '# stderr 1' 'ok 1'
+command_ok_ "$desc: 'ok 1' before 'stderr 2'" -- \
+  check_log_line_order 'ok 1' '# stderr 2'
+
+
 plan_ now
 
 :
-- 
2.48.1