PATCH: fix "missing tests" bug and other improvements to testsuite/runtest.all/libs.exp

[Jacob Bachmeyer]

This patch fixes a bug that could cause test results to be missed in 
libs.exp and adds material to the manual explaining the issue.  While 
adding an entire page worth of text to the manual may seem an unusual 
step in fixing a bug, I wrote it because I had previously hit the same 
bug in code that I had written for my own project's testsuite.  Finding 
that the same bug that had taken me a week to track down (because it was 
inconsistent, depending on the whim of the scheduler whether or not 
additional results would be in the Expect buffer) was also in DejaGnu's 
own testsuite prompted me to document this particular "gotcha" with Expect.

This patch also eliminates the use of temporary files in libs.exp.  
There is no longer any need to dump the output from a failing testcase, 
as it will appear in DejaGnu's log in any case.  The DejaGnu log is no 
longer overwritten by other tests, so that feature is no longer needed.

----
ChangeLog entries:
        * doc/dejagnu.texi (Writing a test case): Add warning about
        priority of Expect patterns, complete with example.
        * testsuite/runtest.all/libs.exp (process_test): Fix bug that
        caused test results other than "PASS" to be skipped if a "PASS" is
        further along in the input buffer.  Describe problem in manual.
        (process_test): Ensure that the log file shows each test case run.
        (process_test): Directly run the test cases instead of using
        temporary files and "cat".  All output is always available in the
        log file, which is no longer overwritten by other tests.
        (process_test): Expect END markers from test case scripts.
        * testsuite/runtest.all/*.test: Emit END markers when done.

----
patch:
----
diff --git a/doc/dejagnu.texi b/doc/dejagnu.texi
index 1a524f0..4764791 100644
--- a/doc/dejagnu.texi
+++ b/doc/dejagnu.texi
@@ -2065,6 +2065,80 @@ misleading. Ideally, a test in this sort of situation 
should not fail
either. Instead, print an error message by calling one of the DejaGnu
procedures @code{error} or @code{warning}.

address@hidden Priority of Expect patterns
+
+Be particularly careful about how you write the patterns.  Expect
+attempts to match each pattern in the order that they are written in
+the @code{expect} command.  Unless a regexp pattern is anchored at the
+beginning of the buffer, Expect can search ahead for a match for a
+pattern that appears earlier in the @code{expect} command and skip
+over text that would match a later pattern.  @emph{The text thus
+skipped is discarded.}  This is a source of very hard to trace bugs,
+especially when reading input from batch-oriented unit tests.
+
+For example, consider a simple model once used by the DejaGnu
+testsuite for unit testing.  In this example, a test has failed, but
+the tests before and after it have passed.  First the relevant input
+to DejaGnu:
+
address@hidden
+PASSED: foo
+FAILED: bar
+PASSED: baz
address@hidden example
+
+The test script is reading this with two Expect patterns, simplified
+for this example by omitting handling of the actual messages and other
+possible results:
+
address@hidden
+expect @{
+       -re @{PASSED: address@hidden @{ pass ... @}
+       -re @{FAILED: address@hidden @{ fail ... @}
address@hidden
address@hidden example
+
+At every cycle, Expect attempts to match each pattern in the order
+that they are written against the available input.  If DejaGnu is
+processing the input as quickly as it arrives, this example will
+actually work.  However, if the system scheduler sets DejaGnu aside
+for a bit, or the external program produces output in a burst, Expect
+can find that its input buffer contains the text in the first example
+above all at once as the cycle begins.
+
+If this occurs, Expect will first attempt to match @address@hidden:
address@hidden against the input and will succeed, since the input
+begins with @samp{PASSED: foo}.  The @code{pass} procedure is called
+and the test result recorded.  Expect then starts a new matching
+cycle.
+
+If the input had been presented one line at a time, the expected
+result would occur: the @address@hidden: address@hidden pattern
+would match and the test driver would work correctly.  But we are
+considering the case where all three lines arrived ``at once'' so we
+must examine what Expect will do in this case.  After the first line
+has been processed, the Expect buffer now contains:
+
address@hidden
+FAILED: bar
+PASSED: baz
address@hidden example
+
+Expect again attempts to match each pattern in order.  Expect will
+attempt to match @address@hidden: address@hidden before attempting
+to match @address@hidden: address@hidden and the first attempt
+succeeds because the pattern is not anchored.  The @samp{FAILED: bar}
+message is simply discarded when Expect finds the later
address@hidden:baz} message in the buffer.
+
+How to prevent this?  There are two ways: either group all of your
+test matches into a single regexp using alternation, or ensure that
+all patterns can match only at the start of Expect's buffer.  Both
+options can be made to work.  Grouping all status results into a
+single regexp allows some other unspecified text to still be silently
+discarded, while ensuring that all patterns are anchored absolutely
+requires closure, as any unmatched text will cause Expect to run out
+of buffer space.  Expect discards the entire buffer when this occurs.

@node Debugging a test case, Adding a test case to a testsuite, Writing a test 
case, Extending DejaGnu
@section Debugging a test case
@@ -5516,4 +5590,5 @@ This makes @code{runtest} exit. Abbreviation: @kbd{q}.

@bye

address@hidden  LocalWords:  subdirectory prepend prepended testsuite filename
address@hidden  LocalWords:  subdirectory prepend prepended testsuite filename 
Expect's
address@hidden  LocalWords:  DejaGnu
diff --git a/testsuite/runtest.all/clone_output.test 
b/testsuite/runtest.all/clone_output.test
index 35cfc31..656f308 100644
--- a/testsuite/runtest.all/clone_output.test
+++ b/testsuite/runtest.all/clone_output.test
@@ -63,3 +63,5 @@ run_tests {
    { lib_pat_test clone_output {"NOTE: Foo"} "NOTE: Foo"
        "clone_output(note) with all_flag set" }
}
+
+puts "END clone_output.test"
diff --git a/testsuite/runtest.all/config.test 
b/testsuite/runtest.all/config.test
index fa959f4..5e0ed82 100644
--- a/testsuite/runtest.all/config.test
+++ b/testsuite/runtest.all/config.test
@@ -90,3 +90,5 @@ run_tests {
    { lib_bool_test isnative {} false   "isnative, canadian cross" }
    { lib_bool_test is3way {} true      "is3way, canadian cross" }
}
+
+puts "END config.test"
diff --git a/testsuite/runtest.all/libs.exp b/testsuite/runtest.all/libs.exp
index e09cd9b..96b443d 100644
--- a/testsuite/runtest.all/libs.exp
+++ b/testsuite/runtest.all/libs.exp
@@ -24,70 +24,57 @@ proc process_test { test } {
    global objdir
    global EXPECT

-    verbose "Executing test case $test"
+    verbose -log "Executing test case $test"
    set text "\[- A-Za-z0-9\,\.\;\"\_\:\'\`\(\)\!\#\=\+\?\&\*]*"

    set timeout 150

    if [file exists $test] {
        verbose "Processing test $test" 2
-       set res [catch {
-           exec -ignorestderr \
-               $EXPECT $test $srcdir $subdir [pwd] \
-               > OUTPUT 2>ERROR
-       }]
-       if { $res } {
-           perror "$test failed" 0

-           set fp [open "OUTPUT" r]
-           set output [read $fp]
-           close $fp
-           puts "$test stdout: >$output<"
-
-           set fp [open "ERROR" r]
-           set error [read $fp]
-           close $fp
-           puts "$test stderr: >$error<"
-       }
-
-       spawn -open [open "|cat OUTPUT" r]
+       spawn -open [open "|$EXPECT $test $srcdir $subdir [pwd]" r]
        expect {
            "No such file or directory" {
                perror "$test wouldn't run" 0
            }
-           -re "\[\r\n\]*NOTSUPPORTED: $text\[\r\n\]*" {
+           -re "^\[^\r\n\]*NOTSUPPORTED: $text\[\r\n\]*" {
                unsupported "[lrange $expect_out(0,string) 1 end]"
                exp_continue
            }
-           -re "\[\r\n\]*NOTTESTED: $text\[\r\n\]*" {
+           -re "^\[^\r\n\]*NOTTESTED: $text\[\r\n\]*" {
                untested "[lrange $expect_out(0,string) 1 end]"
                exp_continue
            }
-           -re "\[\r\n\]*PASSED: $text\[\r\n\]*" {
+           -re "^\[^\r\n\]*PASSED: $text\[\r\n\]*" {
                pass "[lrange $expect_out(0,string) 1 end]"
                exp_continue
            }
-           -re "\[\r\n\]*FAILED: $text\[\r\n\]*" {
+           -re "^\[^\r\n\]*FAILED: $text\[\r\n\]*" {
                fail "[lrange $expect_out(0,string) 1 end]"
                exp_continue
            }
-           -re "\[\r\n\]*WARNED: $text\[\r\n\]*" {
+           -re "^\[^\r\n\]*WARNED: $text\[\r\n\]*" {
                verbose $expect_out(0,string) 2
                exp_continue
            }
-           -re "\[\r\n\]*ERRORED: $text\[\r\n\]*" {
+           -re "^\[^\r\n\]*ERRORED: $text\[\r\n\]*" {
                verbose $expect_out(0,string) 2
                exp_continue
            }
+           -re "^END \[^.\]+\\.test\[\r\n\]*" {
+               close
+           }
+           -re "^\[^\r\n\]+\[\r\n\]+" {
+               exp_continue
+           }
            timeout {
                perror "$test timed out" 0
                exp_continue
            }
            eof {
-               verbose "All Done" 3
+               perror "$test exited early" 0
            }
        }
-       file delete OUTPUT ERROR
    } else {
        perror "$test doesn't exist" 0
    }
diff --git a/testsuite/runtest.all/remote.test 
b/testsuite/runtest.all/remote.test
index 86f3241..78804bd 100644
--- a/testsuite/runtest.all/remote.test
+++ b/testsuite/runtest.all/remote.test
@@ -55,3 +55,5 @@ set target_info(mvme,baud)      "9600"
# Test remote open. We try not to use any of the support procs in
# target.exp to for isolation testing. "target" is the name of the
# default array setup by the procs in target.exp.
+
+puts "END remote.test"
diff --git a/testsuite/runtest.all/target.test 
b/testsuite/runtest.all/target.test
index bd645d2..2da4095 100644
--- a/testsuite/runtest.all/target.test
+++ b/testsuite/runtest.all/target.test
@@ -94,3 +94,5 @@ if { ![info exists target_info(host,name)] } {
} else {
    puts "FAILED: pop_config host"
}
+
+puts "END target.test"
diff --git a/testsuite/runtest.all/testsuite_file.test 
b/testsuite/runtest.all/testsuite_file.test
index c7e13ff..fce65b8 100644
--- a/testsuite/runtest.all/testsuite_file.test
+++ b/testsuite/runtest.all/testsuite_file.test
@@ -209,3 +209,5 @@ if { [file isdirectory [file join $objdir empty-test-dir]] 
} {
}

file delete -force [file join $objdir empty-test-dir]
+
+puts "END testsuite_file.test"
diff --git a/testsuite/runtest.all/utils.test b/testsuite/runtest.all/utils.test
index 107e907..d52019b 100644
--- a/testsuite/runtest.all/utils.test
+++ b/testsuite/runtest.all/utils.test
@@ -211,3 +211,5 @@ run_tests {
    { lib_bool_test runtest_file_p {{foo.exp bar.*} foo.c} false
        "runtest_file_p, foo.exp=bar.* excludes foo.c" }
}
+
+puts "END utils.test"
----


-- Jacob