parallel-tests: make parsing of test results safer
authorStefano Lattarini <stefano.lattarini@gmail.com>
Wed, 29 Jun 2011 14:02:52 +0000 (16:02 +0200)
committerStefano Lattarini <stefano.lattarini@gmail.com>
Wed, 6 Jul 2011 20:43:51 +0000 (22:43 +0200)
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 bug-automake@gnu.org
  =====================================
  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
doc/automake.texi
lib/Automake/tests/Makefile.in
lib/am/check.am
lib/test-driver
tests/Makefile.am
tests/Makefile.in
tests/parallel-tests-no-spurious-summary.test [new file with mode: 0755]
tests/test-driver-end-test-results.test [new file with mode: 0755]

index 6203f89186f5e0f0aa6c859de79cbc1685043efe..f7da174cc70938ed485bf99b1daba99bce762fca 100644 (file)
--- a/ChangeLog
+++ b/ChangeLog
@@ -1,3 +1,39 @@
+2011-07-07  Stefano Lattarini  <stefano.lattarini@gmail.com>
+
+       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 bug-automake@gnu.org
+         =====================================
+         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  <stefano.lattarini@gmail.com>
 
        docs: document custom test drivers and protocols
index a26f2a5c579aaf0e6a97147f0fd7275f0f786129..1e251db37b3ab57a92c9ff889717fd5fb04c644a 100644 (file)
@@ -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
-@option{parallel-tests} driver).
+@option{parallel-tests} 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''
+@code{END}, that will instruct the testsuite harness to stop scanning
+the rest of the log file (this feature is used internally by the default
+@option{parallel-tests} 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
+``non-@code{: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
index e1867fb0ba0cdd37cb16e3fc70e19e9a1260074f..5d3c39fadf6a5eda69af0d42a5abe654ddf9c2f3 100644 (file)
@@ -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'`;                      \
index b02d6c5b262b9dee821ecfcb07f59741e57368ca..f2528e07c3cd1efebd505f7d9d138189f4529679 100644 (file)
@@ -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/^[      ]*//'`; \
index 31640c3f2a7cf40ae80551a8a482729a68d564a5..145bbeae8292c1c1140efbffd633407e35a4f90f 100755 (executable)
@@ -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
index 0b83b0ccfb257a3911d8b4f6eb7fb709366f06de..9c0605d4ea38b30a91f467a59776a908f4b84585 100644 (file)
@@ -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 \
index 193fc9506bf1a6b2d913a050c6ddc0c43d33475f..dc03179817b067a799e86d6507a559d063953c0b 100644 (file)
@@ -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 (executable)
index 0000000..43c54a5
--- /dev/null
@@ -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 (executable)
index 0000000..97c1f29
--- /dev/null
@@ -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
+
+: