AT_CHECK_PROGRESS

[Ralf Wildenhues]

Hello people interested in Autotest progress,

a while ago, we already pondered a bit:
http://thread.gmane.org/gmane.comp.sysutils.autoconf.bugs/5408
about what I called AT_CHECK_INTERACTIVE back then, namely an AT_CHECK
variant that would print output already while the commands were running,
mostly for long-running commands.

I now tried the approach Paul suggested in above thread.  With testsuite
-v, it intermingles stdout and stderr of the tested commands.  It does
not pipe stderr through
  grep '^ *+'

as AT_CHECK does, that would cause output to be buffered again.  Some
other minor details are still wrong, too.

Testing the patch was done by replacing all AT_CHECK with the _PROGRESS
variant internally:

| --- b/lib/autotest/general.m4
| +++ a/lib/autotest/general.m4
| @@ -2013,7 +2013,7 @@ $2[]_ATEOF
|  # This may cause spurious failures when the test suite is run with `-x'.
|  #
|  _AT_DEFINE_SETUP([AT_CHECK],
| -[_AT_CHECK(m4_expand([$1]), [$2], AS_ESCAPE(m4_dquote(m4_expand([$3]))),
| +[_AT_CHECK_PROGRESS(m4_expand([$1]), [$2], 
AS_ESCAPE(m4_dquote(m4_expand([$3]))),
|    AS_ESCAPE(m4_dquote(m4_expand([$4]))), [$5], [$6])])
|  
|  # AT_CHECK_UNQUOTED(COMMANDS, [STATUS = 0], STDOUT, STDERR,

On my test system, this change caused testsuite execution time to
increase by 2%, but no failures otherwise.

The patch below is preliminary.  Before it can be applied, I either need
to find out how to add testsuite exposure for AT_CHECK_PROGRESS similar
to what above delivers.  And do lots of portability testing, and maybe
try some m4 or shell optimization on code size and maybe speed.

Alternatively to a new macro, however, maybe we can even let this
approach eventually serve as the default behavior of AT_CHECK.
What do you think?


The testsuite addition uses a "mutex" strategy to ensure concurrency.
I think this would also be a good idea as replacement for the racy
concurrency tests we currently use for parallel Autotest; I hope to
work on this later.

Thanks,
Ralf

    Autotest: new macro AT_CHECK_PROGRESS.
    
    * doc/autoconf.texi (Writing Testsuites): Document it.
    * tests/autotest.at (progress): New test.
    * NEWS: Update.
    * lib/autotest/general.m4 (AT_INIT)
    <at_fn_check_prepare_notrace, at_fn_check_prepare_trace>:
    Also set at_check_filter_progress.
    <at_fn_filter_trace_progress>: New helper function.
    <PREPARE_TESTS>: Also set at_check_filter_trace_progress.
    <at_fn_group_prepare>: Also set at_status_file1.
    (AT_CHECK_PROGRESS): New macro, copied from AT_CHECK.
    (AT_DIFF_STDERR_P(stderr), AT_DIFF_STDERR_P(stderr))
    (AT_DIFF_STDERR_P(ignore), AT_DIFF_STDERR_P(ignore))
    (AT_DIFF_STDERR_P(experr), AT_DIFF_STDERR_P())
    (AT_DIFF_STDOUT_P(stdout), AT_DIFF_STDOUT_P(stdout))
    (AT_DIFF_STDOUT_P(ignore), AT_DIFF_STDOUT_P(ignore))
    (AT_DIFF_STDOUT_P(expout), AT_DIFF_STDOUT_P())
    (_AT_CHECK_PROGRESS): New helper macros, analogous to their
    AT_CHECK counterparts.

diff --git a/NEWS b/NEWS
index 83f79c7..e3a3a23 100644
--- a/NEWS
+++ b/NEWS
@@ -28,6 +28,9 @@ GNU Autoconf NEWS - User visible changes.
 ** AT_CHECK semantics with respect to the Autotest variable $at_status and
    shell execution environment of the arguments are documented now.
 
+** New Autotest macro AT_CHECK_PROGRESS that produces output while running a
+   test, for tests that run for a long time.
+
 
 * Major changes in Autoconf 2.67 (2010-07-21) [stable]
   Released by Eric Blake, based on git versions 2.66.*.
diff --git a/doc/autoconf.texi b/doc/autoconf.texi
index 6217c02..d3a1cea 100644
--- a/doc/autoconf.texi
+++ b/doc/autoconf.texi
@@ -24155,8 +24155,11 @@ be a single shell word that expands into a single file 
name.
   @ovar{stderr}, @ovar{run-if-fail}, @ovar{run-if-pass})
 @defmacx AT_CHECK_UNQUOTED (@var{commands}, @dvar{status, 0}, @ovar{stdout}, @
   @ovar{stderr}, @ovar{run-if-fail}, @ovar{run-if-pass})
address@hidden AT_CHECK_PROGRESS (@var{commands}, @dvar{status, 0}, 
@ovar{stdout}, @
+  @ovar{stderr}, @ovar{run-if-fail}, @ovar{run-if-pass})
 @atindex{CHECK}
 @atindex{CHECK_UNQUOTED}
address@hidden
 @vrindex at_status
 Execute a test by performing given shell @var{commands} in a subshell.
 @var{commands} is output as-is, so shell expansions are honored.  These
@@ -24194,7 +24197,10 @@ escaping (@samp{\}) on comparison text given in the 
@var{stdout} and
 @var{stderr} arguments; if the text includes a trailing newline, this
 would be the same as if it were specified via an unquoted
 here-document.  (However, there is no difference in the interpretation
-of @var{commands}).
+of @var{commands}).  The difference between @code{AT_CHECK} and
address@hidden is that the latter tries to produce verbose
+output already while @var{commands} are still running, at the cost of
+some extra Autotest artefacts found in the verbose output.
 
 @table @samp
 @item ignore
diff --git a/lib/autotest/general.m4 b/lib/autotest/general.m4
index 344c7e9..f6ab230 100644
--- a/lib/autotest/general.m4
+++ b/lib/autotest/general.m4
@@ -260,7 +260,7 @@ at_fn_check_prepare_notrace ()
 {
   $at_trace_echo "Not enabling shell tracing (command contains $[1])"
   AS_ECHO(["$[2]"]) >"$at_check_line_file"
-  at_check_trace=: at_check_filter=:
+  at_check_trace=: at_check_filter=: at_check_filter_progress=:
   : >"$at_stdout"; : >"$at_stderr"
 }
 
@@ -271,6 +271,7 @@ at_fn_check_prepare_trace ()
 {
   AS_ECHO(["$[1]"]) >"$at_check_line_file"
   at_check_trace=$at_traceon at_check_filter=$at_check_filter_trace
+  at_check_filter_progress=$at_check_filter_trace_progress
   : >"$at_stdout"; : >"$at_stderr"
 }
 
@@ -297,6 +298,15 @@ at_fn_filter_trace ()
   grep -v '^ *+' "$at_stder1" >"$at_stderr"
 }
 
+AS_FUNCTION_DESCRIBE([at_fn_filter_trace_progress], [],
+[Remove the lines in the file "$at_stderr" generated by "set -x" and print
+them to stderr.  This macro is for the AT_CHECK_PROGRESS variant.])
+at_fn_filter_trace_progress ()
+{
+  mv "$at_stderr" "$at_stder1"
+  grep -v '^ *+' "$at_stder1" >"$at_stderr"
+}
+
 AS_FUNCTION_DESCRIBE([at_fn_log_failure], [FILE-LIST],
 [Copy the files in the list on stdout with a "> " prefix, and exit the shell
 with a failure exit code.])
@@ -394,6 +404,7 @@ at_jobs=1
 at_traceon=:
 at_trace_echo=:
 at_check_filter_trace=:
+at_check_filter_trace_progress=:
 
 # Shall we keep the debug scripts?  Must be `:' when the suite is
 # run by a debug script, so that the script doesn't remove itself.
@@ -529,6 +540,7 @@ do
        at_traceon='set -x'
        at_trace_echo=echo
        at_check_filter_trace=at_fn_filter_trace
+        at_check_filter_trace_progress=at_fn_filter_trace_progress
        ;;
 
     [[0-9] | [0-9][0-9] | [0-9][0-9][0-9] | [0-9][0-9][0-9][0-9]])
@@ -1107,8 +1119,10 @@ at_fn_group_prepare ()
   at_job_dir=$at_helper_dir/$at_group
   # The file containing the location of the last AT_CHECK.
   at_check_line_file=$at_job_dir/check-line
-  # The file containing the exit status of the last command.
+  # The file containing the exit status of the last check.
   at_status_file=$at_job_dir/status
+  # The file containing the exit status of the last command.
+  at_status_file1=$at_job_dir/status1
   # The files containing the output of the tested commands.
   at_stdout=$at_job_dir/stdout
   at_stder1=$at_job_dir/stder1
@@ -2020,6 +2034,17 @@ m4_define([AT_CHECK_NOESCAPE],
 [_AT_CHECK(m4_expand([$1]), [$2], m4_expand([$3]),
   m4_expand([$4]), [$5], [$6])])
 
+# AT_CHECK_PROGRESS(COMMANDS, [STATUS = 0], STDOUT, STDERR,
+#                   [RUN-IF-FAIL], [RUN-IF-PASS])
+# ---------------------------------------------------------
+# Like AT_CHECK, but in verbose mode, allow to show output progress already
+# while COMMANDS are still running.  This is intended for very long-running
+# tests where the actual output is intended to be read by a human during
+# execution.
+_AT_DEFINE_SETUP([AT_CHECK_PROGRESS],
+[_AT_CHECK_PROGRESS(m4_expand([$1]), [$2],
+  AS_ESCAPE(m4_dquote(m4_expand([$3]))),
+  AS_ESCAPE(m4_dquote(m4_expand([$4]))), [$5], [$6])])
 
 # _AT_DECIDE_TRACEABLE(COMMANDS)
 # ------------------------------
@@ -2149,6 +2174,28 @@ m4_define([AT_DIFF_STDOUT(expout)],
 m4_define([AT_DIFF_STDOUT()],
          [at_fn_diff_devnull "$at_stdout" || at_failed=:])
 
+m4_define([AT_DIFF_STDERR_P(stderr)],
+         [cp "$at_stderr" stderr])
+m4_define([AT_DIFF_STDERR_P(stderr-nolog)],
+         [echo stderr captured; cp "$at_stderr" stderr])
+m4_define([AT_DIFF_STDERR_P(ignore)])
+m4_define([AT_DIFF_STDERR_P(ignore-nolog)])
+m4_define([AT_DIFF_STDERR_P(experr)],
+         [$at_diff experr "$at_stderr" || at_failed=:])
+m4_define([AT_DIFF_STDERR_P()],
+         [at_fn_diff_devnull "$at_stderr" || at_failed=:])
+
+m4_define([AT_DIFF_STDOUT_P(stdout)],
+         [cp "$at_stdout" stdout])
+m4_define([AT_DIFF_STDOUT_P(stdout-nolog)],
+         [echo stdout captured; cp "$at_stdout" stdout])
+m4_define([AT_DIFF_STDOUT_P(ignore)])
+m4_define([AT_DIFF_STDOUT_P(ignore-nolog)])
+m4_define([AT_DIFF_STDOUT_P(expout)],
+         [$at_diff expout "$at_stdout" || at_failed=:])
+m4_define([AT_DIFF_STDOUT_P()],
+         [at_fn_diff_devnull "$at_stdout" || at_failed=:])
+
 # _AT_CHECK(COMMANDS, [STATUS = 0], STDOUT, STDERR,
 #           [RUN-IF-FAIL], [RUN-IF-PASS])
 # -------------------------------------------------
@@ -2205,6 +2252,52 @@ m4_ifvaln([$5$6], [AS_IF($at_failed, [$5], [$6])])]dnl
 $at_traceon; }
 ])# _AT_CHECK
 
+# _AT_CHECK_PROGRESS(COMMANDS, [STATUS = 0], STDOUT, STDERR,
+#           [RUN-IF-FAIL], [RUN-IF-PASS])
+# ----------------------------------------------------------
+m4_define([_AT_CHECK_PROGRESS],
+[m4_define([AT_ingroup])]dnl
+[{ set +x
+AS_ECHO(["$at_srcdir/AT_LINE: AS_ESCAPE([[$1]])"])
+_AT_DECIDE_TRACEABLE([$1]) _AT_LINE_ESCAPED
+m4_pushdef([at_outlog],
+          [m4_case([$3],
+                   [stdout-nolog], [>> "$at_stdout"],
+                   [expout], [>> "$at_stdout"],
+                   [ignore], [],
+                   [ignore-nolog], [>/dev/null],
+                   [| tee -a "$at_stdout"])])dnl
+m4_pushdef([at_errlog],
+          [m4_case([$4],
+                   [stderr-nolog], [4>>"$at_stderr"],
+                   [experr], [4>>"$at_stderr"],
+                   [ignore], [],
+                   [ignore-nolog], [4>/dev/null],
+                   [4>&1 >&3 | tee -a "$at_stderr" >&2])])dnl
+exec 3>&1 4>&2
+( ( ($at_check_trace; [$1]
+    ) 2>&4 3>&- 4>&-; echo $? >"$at_status_file1") \
+  at_outlog ) at_errlog
+exec 3>&- 4>&-
+at_failed=false
+read at_status <"$at_status_file1"
+$at_check_filter_progress
+m4_ifdef([AT_DIFF_STDERR_P($4)], [m4_indir([AT_DIFF_STDERR_P($4)])],
+  [echo >>"$at_stderr"; AS_ECHO([["$4"]]) | \
+  $at_diff - "$at_stderr" || at_failed=:])
+m4_ifdef([AT_DIFF_STDOUT_P($3)], [m4_indir([AT_DIFF_STDOUT_P($3)])],
+  [echo >>"$at_stdout"; AS_ECHO([["$3"]]) | \
+  $at_diff - "$at_stdout" || at_failed=:])
+m4_if([$2], [ignore], [at_fn_check_skip],
+  [at_fn_check_status m4_default([$2], [0])]) $at_status "$at_srcdir/AT_LINE"
+m4_ifvaln([$5$6], [AS_IF($at_failed, [$5], [$6])])]dnl
+[$at_failed && at_fn_log_failure AT_capture_files
+$at_traceon; }
+m4_popdef([at_outlog])dnl
+m4_popdef([at_errlog])dnl
+])# _AT_CHECK_PROGRESS
+
+
 # _AT_CHECK_EXIT(COMMANDS, [EXIT-STATUS-IF-PASS])
 # -----------------------------------------------
 # Minimal version of _AT_CHECK for AT_SKIP_IF and AT_FAIL_IF.
diff --git a/tests/autotest.at b/tests/autotest.at
index ab04dbe..2342799 100644
--- a/tests/autotest.at
+++ b/tests/autotest.at
@@ -551,6 +551,24 @@ AT_CHECK_AT([Binary output],
    AT_CHECK([$CONFIG_SHELL ./micro-suite 6], [1], [ignore], [ignore])], [1-3])
 
 
+AT_CHECK_AT_TEST([progress],
+  [AT_CHECK_PROGRESS([echo starting; mkdir "$stamp"; ]dnl
+                    [while test -d "$stamp"; do sleep 1; done; ]dnl
+                    [echo done], [], [ignore], [ignore])
+], [], [0], [stdout], [stderr], [],
+   [# To ensure progress, we exploit an internal detail of AT_CHECK here,
+   # namely, that it captures output in $at_stdout.
+   stamp=`pwd`/stamp
+   export stamp
+   AT_CHECK([$CONFIG_SHELL ./micro-suite -v & ]dnl
+           [while test ! -d "$stamp"; do sleep 1; done; ]dnl
+           [echo intermixed >>"$at_stdout"; ]dnl
+           [rmdir "$stamp"; wait],
+           [], [stdout], [ignore])
+   AT_CHECK([sed -n '/^starting/,/^done/p' stdout | grep intermixed], [], 
[ignore])
+], [-k none])
+
+
 AT_CHECK_AT_TEST([Cleanup],
   [AT_CHECK([test ! -f cleanup.success && test ! -f cleanup.failure])
    AT_XFAIL_IF([$xfail])