[PATCH] parallel-tests: make parsing of test results safer (was: Re: [PATCH] {test-protocols} parallel-tests: fix bug in Automake's own testsuite)

[Stefano Lattarini]

Reference:
 <http://lists.gnu.org/archive/html/automake-patches/2011-06/msg00199.html>

The new code for parsing the testsuite-generated `.log' files,
as introduced in commit `v1.11-872-gc96b881', considers each
`:test-result:' field anywhere in a `.log' file as a declaration
of a test result, and accounts for it as such in the testsuite
summary.  Unfortunately this could easily cause spurious test
failures being reported in the testsuite summary.  This happened
in practice with the Automake's own testsuite; for example:

  $ make check TESTS='check12-p.test'; echo exit: $?
  ...
  PASS: check12-p.test
  =====================================
  4 of 5 tests failed
  See tests/test-suite.log
  Please report to address@hidden
  =====================================
  make[2]: *** [test-suite.log] Error 1
  make: *** [check-am] Error 2
  exit: 2

This change introduces a new special `:test-result:' "END", that,
when seen, prevents the rest of the log file from being parsed.

OK for the 'test-protocols' branch?

Regards,
  Stefano

From 310e80b275ed120af4999e0dad018b8a5732fd02 Mon Sep 17 00:00:00 2001
Message-Id: <address@hidden>
From: Stefano Lattarini <address@hidden>
Date: Wed, 29 Jun 2011 16:02:52 +0200
Subject: [PATCH] parallel-tests: make parsing of test results safer

The new code for parsing the testsuite-generated `.log' files,
as introduced in commit `v1.11-872-gc96b881', considers each
`:test-result:' field anywhere in a `.log' file as a declaration
of a test result, and accounts for it as such in the testsuite
summary.  Unfortunately this could easily cause spurious test
failures being reported in the testsuite summary.  This happened
in practice with the Automake's own testsuite; for example:

  $ make check TESTS='check12-p.test'; echo exit: $?
  ...
  PASS: check12-p.test
  =====================================
  4 of 5 tests failed
  See tests/test-suite.log
  Please report to address@hidden
  =====================================
  make[2]: *** [test-suite.log] Error 1
  make: *** [check-am] Error 2
  exit: 2

This change introduces a new special `:test-result:' "END", that,
when seen, prevents the rest of the log file from being parsed.

For more information, refer to the thread:
<http://lists.gnu.org/archive/html/automake-patches/2011-06/msg00199.html>

* lib/am/check.am ($(TEST_SUITE_LOG)): Stop the parsing of a log
file as soon as the special ":test-result:END" directive is seen.
Related changes and enhancements.
* lib/test-driver: Protect the rest of the log after the result
lined with a ":test-result:END" directive.
* tests/parallel-tests-no-spurious-summary.test: New test.
* tests/test-driver-end-test-results.test: Likewise.
* tests/Makefile.am (TESTS): Update.
---
 ChangeLog                                     |   36 ++++++++++
 doc/automake.texi                             |   21 +++++--
 lib/Automake/tests/Makefile.in                |   16 ++++-
 lib/am/check.am                               |   31 +++++++-
 lib/test-driver                               |    6 +-
 tests/Makefile.am                             |    2 +
 tests/Makefile.in                             |   18 ++++-
 tests/parallel-tests-no-spurious-summary.test |   66 ++++++++++++++++++
 tests/test-driver-end-test-results.test       |   91 +++++++++++++++++++++++++
 9 files changed, 270 insertions(+), 17 deletions(-)
 create mode 100755 tests/parallel-tests-no-spurious-summary.test
 create mode 100755 tests/test-driver-end-test-results.test

diff --git a/ChangeLog b/ChangeLog
index 6203f89..ab7ba2f 100644
--- a/ChangeLog
+++ b/ChangeLog
@@ -1,5 +1,41 @@
 2011-06-29  Stefano Lattarini  <address@hidden>
 
+       parallel-tests: make parsing of test results safer
+       The new code for parsing the testsuite-generated `.log' files,
+       as introduced in commit `v1.11-872-gc96b881', considers each
+       `:test-result:' field anywhere in a `.log' file as a declaration
+       of a test result, and accounts for it as such in the testsuite
+       summary.  Unfortunately this could easily cause spurious test
+       failures being reported in the testsuite summary.  This happened
+       in practice with the Automake's own testsuite; for example:
+         $ make check TESTS='check12-p.test'; echo exit: $?
+         ...
+         PASS: check12-p.test
+         =====================================
+         4 of 5 tests failed
+         See tests/test-suite.log
+         Please report to address@hidden
+         =====================================
+         make[2]: *** [test-suite.log] Error 1
+         make: *** [check-am] Error 2
+         exit: 2
+       This change introduces a new special `:test-result:' "END", that,
+       when seen, prevents the rest of the log file from being parsed.
+       For more information, refer to the thread:
+       
<http://lists.gnu.org/archive/html/automake-patches/2011-06/msg00199.html>
+       * lib/am/check.am ($(TEST_SUITE_LOG)): Stop the parsing of a log
+       file as soon as the special ":test-result:END" directive is seen.
+       Related changes and enhancements.
+       * lib/test-driver: Protect the rest of the log after the result
+       lined with a ":test-result:END" directive.
+       * doc/automake.texi (Log files generation and test results
+       recording): Update, and related improvements.
+       * tests/parallel-tests-no-spurious-summary.test: New test.
+       * tests/test-driver-end-test-results.test: Likewise.
+       * tests/Makefile.am (TESTS): Update.
+
+2011-06-29  Stefano Lattarini  <address@hidden>
+
        docs: document custom test drivers and protocols
        * doc/automake.texi (Simple Tests): Note that the TESTS_ENVIRONMENT
        use suggested here is not portable to 'parallel-tests'.
diff --git a/doc/automake.texi b/doc/automake.texi
index a26f2a5..1e251db 100644
--- a/doc/automake.texi
+++ b/doc/automake.texi
@@ -9242,7 +9242,9 @@ testsuite summary to be correct in this case, the test 
driver must
 register @emph{each} such result in the generated @file{.log} file, using
 the @code{:test-result:} reStructuredText field.  Otherwise, only the
 global test result will be considered (as it is the case of the default
address@hidden driver).
address@hidden driver).  Note that such a field will be
+recognized only when used @emph{exactly} at the beginning of a line:
+leading whitespace will not be ignored.
 
 @c Keep this in sync with lib/am/check-am:$(TEST_SUITE_LOG).
 The only recognized test results are currently @code{PASS}, @code{XFAIL},
@@ -9251,8 +9253,15 @@ with @code{:test-result:}, can be optionally followed by 
text holding
 the name and/or a brief description of the corresponding test; the
 @option{parallel-tests} harness will ignore such extra text when
 generating @file{test-suite.log} and preparing the testsuite summary.
+Also, @code{:test-result:} can be used with a special ``pseudo-result''
address@hidden, that will instruct the testsuite harness to stop scanning
+the rest of the log file (this feature is used internally by the default
address@hidden driver, and can be useful to avoid spurious
+testsuite results).
 
-For example, if a @file{.log} file contains the following lines:
+Let's see a small example.  If a @file{.log} file contains the following
+lines (exactly in this order, but possibly interleaved with other
address@hidden:test-results:}'' lines):
 
 @example
 :test-result: PASS server starts
@@ -9260,12 +9269,14 @@ For example, if a @file{.log} file contains the 
following lines:
 :test-result: FAIL HTTP/1.0 request
 :test-result: SKIP HTTPS request (TLS library wasn't available)
 :test-result: PASS server stops
+:test-result: END
+:test-result: XPASS (this shouldn't be parsed as a test result)
 @end example
 
 @noindent
-it means that the corresponding test script contributes with five test
-results to the testsuite summary (three of these tests being successful,
-one failed, and one skipped).
+it means that the corresponding test script contributes with @emph{five}
+test results to the testsuite summary (three of these tests being
+successful, one failed, and one skipped).
 
 @c FIXME: currently, the @code{:test-result:} field is recognized anywhere
 @c in the @file{.log} file; this is possibly prone to generating spurious
diff --git a/lib/Automake/tests/Makefile.in b/lib/Automake/tests/Makefile.in
index e1867fb..5d3c39f 100644
--- a/lib/Automake/tests/Makefile.in
+++ b/lib/Automake/tests/Makefile.in
@@ -345,13 +345,23 @@ cscope cscopelist:
 $(TEST_SUITE_LOG): $(TEST_LOGS)
        @$(am__sh_e_setup); \
        rst_magic=":test-result:"; \
+       nlinit=`echo 'nl="'; echo '"'`; eval "$$nlinit"; unset nlinit; \
        list='$(TEST_LOGS)'; \
        list2=`for f in $$list; do test ! -r $$f || echo $$f; done`; \
        results1=`for f in $$list; do test -r $$f || echo FAIL; done`; \
        results2=''; \
-       if test -n "$$list2"; then \
-         results2=`sed -n "s/^$$rst_magic[      ]*//p" $$list2`; \
-       fi; \
+       exec 5<&0; \
+       for f in $$list2; do \
+         exec 0<$$f; \
+         while read line; do \
+           case $$line in $$rst_magic*);; *) continue;; esac; \
+           res=`expr "x$$line" : "x$$rst_magic[         ]*\\\\(.*\\\\)$$"`; \
+           case $$res in END*) break;; esac; \
+           results2="$$results2$$nl$$res"; \
+         done; \
+         exec 0<&5; \
+       done; \
+       exec 5<&-; \
        results=`echo "$$results1" && echo "$$results2"` \
        all=`echo "$$results" | sed '/^$$/d' | wc -l | sed -e 's/^[      
]*//'`; \
        fail=`echo "$$results" | grep -c '^FAIL'`;                      \
diff --git a/lib/am/check.am b/lib/am/check.am
index b02d6c5..f2528e0 100644
--- a/lib/am/check.am
+++ b/lib/am/check.am
@@ -145,17 +145,40 @@ $(TEST_SUITE_LOG): $(TEST_LOGS)
 ## SubUnit, where a single test script can run multiple tests, each
 ## with its own outcome.
        rst_magic=":test-result:"; \
+## The following line will define the `$nl' shell variable to a literal
+## newline.  Idiom taken from the Autoconf manual.
+       nlinit=`echo 'nl="'; echo '"'`; eval "$$nlinit"; unset nlinit; \
 ## All test logs.
        list='$(TEST_LOGS)'; \
 ## Readable test logs.
        list2=`for f in $$list; do test ! -r $$f || echo $$f; done`; \
 ## Each unreadable test log counts as a failed test.
        results1=`for f in $$list; do test -r $$f || echo FAIL; done`; \
-## Extract the outcome of all the testcases from the test logs.
+## Now we're going to extract the outcome of all the testcases from the
+## test logs.
        results2=''; \
-       if test -n "$$list2"; then \
-         results2=`sed -n "s/^$$rst_magic[      ]*//p" $$list2`; \
-       fi; \
+## Can't do the redirections directly in the "for" loop below, otherwise
+## some shells would run the loop body in a subshell.
+       exec 5<&0; \
+       for f in $$list2; do \
+         exec 0<$$f; \
+         while read line; do \
+## Ignore lines that do not declare test results.
+           case $$line in $$rst_magic*);; *) continue;; esac; \
+## The test result declared by this line goes in $res.
+           res=`expr "x$$line" : "x$$rst_magic[         ]*\\\\(.*\\\\)$$"`; \
+## A special result of "END" means that the rest of the log is not to be
+## scanned.  Be a little lax in matching such special result, to allow
+## for e.g., trailing whitespace or punctuation.
+           case $$res in END*) break;; esac; \
+## Otherwise register the result.
+           results2="$$results2$$nl$$res"; \
+         done; \
+## Restore original standard input.
+         exec 0<&5; \
+       done; \
+## We don't need this anymore.
+       exec 5<&-; \
 ## Prepare the test suite summary.
        results=`echo "$$results1" && echo "$$results2"` \
        all=`echo "$$results" | sed '/^$$/d' | wc -l | sed -e 's/^[      
]*//'`; \
diff --git a/lib/test-driver b/lib/test-driver
index 31640c3..145bbea 100755
--- a/lib/test-driver
+++ b/lib/test-driver
@@ -1,7 +1,7 @@
 #! /bin/sh
 # test-driver - basic driver script for the `parallel-tests' mode.
 
-scriptversion=2011-06-21.19; # UTC
+scriptversion=2011-06-29.13; # UTC
 
 # Copyright (C) 2011 Free Software Foundation, Inc.
 #
@@ -121,9 +121,11 @@ echo "${col}${res}${std}: $test_name"
 {
   echo "$res: $test_name (exit: $estatus)" | rst_section
   echo ":test-result: $res (exit status: $estatus)"
+  echo
+  echo ":test-result:END"
+  echo
   # Use a reStructuredText transition to better separate the test
   # outcome report from its registered output.
-  echo
   echo ------------
   echo
   cat $tmpfile
diff --git a/tests/Makefile.am b/tests/Makefile.am
index 0b83b0c..9c0605d 100644
--- a/tests/Makefile.am
+++ b/tests/Makefile.am
@@ -730,6 +730,8 @@ parallel-tests-log-override-2.test \
 parallel-tests-log-override-recheck.test \
 parallel-tests-empty-testlogs.test \
 parallel-test-driver-install.test \
+parallel-tests-no-spurious-summary.test \
+test-driver-end-test-results.test \
 test-driver-custom-no-extra-driver.test \
 test-driver-custom.test \
 test-driver-custom-xfail-tests.test \
diff --git a/tests/Makefile.in b/tests/Makefile.in
index 193fc95..dc03179 100644
--- a/tests/Makefile.in
+++ b/tests/Makefile.in
@@ -990,6 +990,8 @@ parallel-tests-log-override-2.test \
 parallel-tests-log-override-recheck.test \
 parallel-tests-empty-testlogs.test \
 parallel-test-driver-install.test \
+parallel-tests-no-spurious-summary.test \
+test-driver-end-test-results.test \
 test-driver-custom-no-extra-driver.test \
 test-driver-custom.test \
 test-driver-custom-xfail-tests.test \
@@ -1395,13 +1397,23 @@ cscope cscopelist:
 $(TEST_SUITE_LOG): $(TEST_LOGS)
        @$(am__sh_e_setup); \
        rst_magic=":test-result:"; \
+       nlinit=`echo 'nl="'; echo '"'`; eval "$$nlinit"; unset nlinit; \
        list='$(TEST_LOGS)'; \
        list2=`for f in $$list; do test ! -r $$f || echo $$f; done`; \
        results1=`for f in $$list; do test -r $$f || echo FAIL; done`; \
        results2=''; \
-       if test -n "$$list2"; then \
-         results2=`sed -n "s/^$$rst_magic[      ]*//p" $$list2`; \
-       fi; \
+       exec 5<&0; \
+       for f in $$list2; do \
+         exec 0<$$f; \
+         while read line; do \
+           case $$line in $$rst_magic*);; *) continue;; esac; \
+           res=`expr "x$$line" : "x$$rst_magic[         ]*\\\\(.*\\\\)$$"`; \
+           case $$res in END*) break;; esac; \
+           results2="$$results2$$nl$$res"; \
+         done; \
+         exec 0<&5; \
+       done; \
+       exec 5<&-; \
        results=`echo "$$results1" && echo "$$results2"` \
        all=`echo "$$results" | sed '/^$$/d' | wc -l | sed -e 's/^[      
]*//'`; \
        fail=`echo "$$results" | grep -c '^FAIL'`;                      \
diff --git a/tests/parallel-tests-no-spurious-summary.test 
b/tests/parallel-tests-no-spurious-summary.test
new file mode 100755
index 0000000..43c54a5
--- /dev/null
+++ b/tests/parallel-tests-no-spurious-summary.test
@@ -0,0 +1,66 @@
+#! /bin/sh
+# Copyright (C) 2009, 2010, 2011 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 <http://www.gnu.org/licenses/>.
+
+# Check that `:test-results:' directives in test scripts' output doesn't
+# originate spurious results in the testsuite summary.
+
+parallel_tests=yes
+. ./defs || Exit 1
+
+cat >> configure.in << 'END'
+AC_OUTPUT
+END
+
+cat > Makefile.am << 'END'
+TESTS = foo.test bar.test
+END
+
+cat > foo.test <<'END'
+#! /bin/sh
+echo :test-result:XFAIL
+echo :test-result: SKIP
+exit 0
+END
+cat > bar.test <<'END'
+#! /bin/sh
+echo :test-result:FAIL
+echo :test-result: XPASS
+exit 0
+END
+chmod a+x foo.test bar.test
+
+$ACLOCAL
+$AUTOCONF
+$AUTOMAKE -a
+
+./configure
+
+st=0
+$MAKE check >output 2>&1 || st=$?
+cat output
+cat test-suite.log
+cat foo.log
+test $st -eq 0 || Exit $st
+
+grep '^:test-result:XFAIL$'  foo.log
+grep '^:test-result: SKIP$'  foo.log
+grep '^:test-result:FAIL$'   bar.log
+grep '^:test-result: XPASS$' bar.log
+
+$EGREP '^(All)? 2 tests? passed' output
+$EGREP 'did not behave|unexpected pass|not run' output && Exit 1
+
+:
diff --git a/tests/test-driver-end-test-results.test 
b/tests/test-driver-end-test-results.test
new file mode 100755
index 0000000..97c1f29
--- /dev/null
+++ b/tests/test-driver-end-test-results.test
@@ -0,0 +1,91 @@
+#! /bin/sh
+# Copyright (C) 2011 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 <http://www.gnu.org/licenses/>.
+
+# parallel-tests harness: check that a special ":test-result:END"
+# directive prevents the code generating the testsuite summary and
+# the test-suite.log from parsing the rest of the log file.
+
+parallel_tests=yes
+. ./defs || Exit 1
+
+cat >> configure.in << 'END'
+AC_OUTPUT
+END
+
+cat > Makefile.am << 'END'
+TEST_LOG_DRIVER = ./dummy-driver
+TESTS = a.test b.test c.test d.test
+END
+
+cat > dummy-driver <<'END'
+#!/bin/sh
+set -e
+while test $# -gt 0; do
+  case $1 in
+    --log-file) log_file=$2; shift;;
+    --test-name|--expect-failure|--color-tests|--enable-hard-errors) shift;;
+    --) shift; break;;
+     *) echo "$0: invalid option/argument: '$1'" >&2; exit 2;;
+  esac
+  shift
+done
+cp $1 $log_file
+END
+chmod a+x dummy-driver
+
+cat > a.test <<'END'
+PASS: a.test
+:test-result:END
+:test-result:FAIL
+END
+
+cat > b.test <<END
+PASS: b.test
+:test-result:PASS
+:test-result:END
+:test-result:FAIL
+END
+
+cat > c.test <<END
+PASS: c.test
+:test-result:SKIP
+:test-result: END$tab  $tab$tab
+:test-result:XPASS
+END
+
+cat > d.test <<END
+PASS: d.test
+:test-result:PASS
+:test-result:PASS
+:test-result: $tab  END.
+:test-result:FAIL
+END
+
+$ACLOCAL
+$AUTOCONF
+$AUTOMAKE
+
+./configure
+
+$MAKE check >output 2>&1 || { cat output; Exit 1; }
+cat output
+cat a.log; cat b.log; cat c.log; cat d.log # For debugging.
+
+$EGREP '^(All)? 3 tests? passed' output
+grep '^(1 test.* not run' output
+$EGREP 'did not behave|unexpected pass' output && Exit 1
+
+:
-- 
1.7.2.3