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 <rhan...@rhansen.org>
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 <rhan...@rhansen.org>
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 <rhan...@rhansen.org>
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
OpenPGP_signature.asc
Description: OpenPGP digital signature
