X-Spam-Check-By: sourceware.org
Content-class: urn:content-classes:message
MIME-Version: 1.0
Content-Type: text/plain; 	charset="us-ascii"
Subject: Expect's timeout value is ignored
Date: Mon, 4 Jun 2007 16:41:27 -0000
Message-ID: <7AF99FB70194CF47AC578B95FF2F6E3902248C90@G3W0066.americas.hpqcorp.net>
From: "Busse, Dale" <dale DOT busse AT hp DOT com>
To: <cygwin AT cygwin DOT com>
Mailing-List: contact cygwin-help AT cygwin DOT com; run by ezmlm
List-Id: <cygwin.cygwin.com>
List-Subscribe: <mailto:cygwin-subscribe AT cygwin DOT com>
List-Archive: <http://sourceware.org/ml/cygwin/>
List-Post: <mailto:cygwin AT cygwin DOT com>
List-Help: <mailto:cygwin-help AT cygwin DOT com>, <http://sourceware.org/ml/#faqs>
Sender: cygwin-owner AT cygwin DOT com
Mail-Followup-To: cygwin AT cygwin DOT com
Delivered-To: mailing list cygwin AT cygwin DOT com
Content-Transfer-Encoding: 8bit
X-MIME-Autoconverted: from quoted-printable to 8bit by delorie.com id l54GgPgj009115

In a nutshell, Expect doesn't seem to be waiting for the specified
timeout interval.  Here's the send/expect command pair that generates
the error (lines preceded by '*' were added for diagnostic purposes):

send_gdb "print v_int <= v_short\r"
*set time [timestamp];
*verbose "time: $time" 3
*sleep 10
*set time [timestamp];
*verbose "time: $time" 3
 gdb_expect {
    -re ".*$false.*$gdb_prompt$" {
        pass "print value of v_int<=v_short"
      }
    -re ".*$gdb_prompt$" { fail "print value of v_int<=v_short" }
    timeout           { fail "(timeout) print value of v_int<=v_short" }
  }

Here's the output when I've enabled verbose and used the --debug flag:

send: sending "print v_int <= v_short\r" to { 8 }
time: 1180650756
time: 1180650766

So, we've waited 10 seconds following the send command before issuing
the expect command.  Here's the code for proc remote_expect (the
ultimate callee from gdb_expect) in \dejagnu\lib\remote.exp (my
additions preceded by '*'):

    if ![info exists code] {
*        set timeout 10
        set res "\n-timeout $timeout $res";
        set body "expect \{\n-i $spawn_id -timeout $timeout $orig\}";
*        verbose "remote_expect body = '$body'..." 3
*        set time [timestamp];
*        verbose "time is $time..." 3
        set code [catch {uplevel $body} string];
*        set time [timestamp];
*        verbose "time is $time..." 3
    }

Here's the output from dbg.log:

1727     remote_expect body = 'expect {
1728     -i 8 -timeout 10
1729         -re ".*$false.*$gdb_prompt$" {
1730             pass "print value of v_int<=v_short"
1731           }
1732         -re ".*$gdb_prompt$" { fail "print value of v_int<=v_short"
}
1733         timeout           { fail "(timeout) print value of
v_int<=v_short
1734       }'...
1735     time is 1180650766...
1736     time is 1180650766...
1737     remote_expect error_sect = ' fail "(timeout) print value of
v_int<=v_short
1738     FAIL: gdb.base/aaa.exp: (timeout) print value of v_int<=v_short

Note that the call returns in less than 1 second and there is no output
of the form:
expect: does "..." (spawn_id 8) match regular expression...
which seems to indicate that no pattern matching is even attempted.  So
what happened to the 10 second timeout?

Interestingly, the expected output does show up within the same second,
but now the script has moved on to the next test, which passes based on
output from the previous test, not the current test:

 1772     remote_expect body = 'expect {
 1773     -i 8 -timeout 10
 1774         -re ".*1.*$gdb_prompt$" {
 1775             pass "print value of v_int<=v_signed_char"
 1776           }
 1777         -re ".*$gdb_prompt$" { fail "print value of
v_int<=v_signed_char"
 1778         timeout           { fail "(timeout) print value of
v_int<=v_signed_char
 1779       }'...
 1780     time is 1180650766...
 1781
 1782     expect: does "" (spawn_id 8) match regular expression
".*1.*\(eInspect [0-9]+,[0-9]+\):$"? no
 1783     ".*\(eInspect [0-9]+,[0-9]+\):$"? no
 1784     print v_int <= v_short
 1785     $15 = 0
 1786     (eInspect 3,536):
 1787     expect: does "print v_int <= v_short\r\r\n$15 =
0\r\r\n(eInspect 3,53):" (spawn_id 8) match regular expression
".*1.*\(eInspect [0-9]+,[0-9]+\):$"? yes
 1788     expect: set expect_out(0,string) "print v_int <=
v_short\r\r\n$15 = 0\r\r\n(eInspect 3,536):"
 1789     expect: set expect_out(spawn_id) "8"
 1790     expect: set expect_out(buffer) "print v_int <=
v_short\r\r\n$15 = 0\r\r\n(eInspect 3,536):"
 1791     PASS: gdb.base/aaa.exp: print value of v_int<=v_signed_char
 1792     time is 1180650766...

Any help you can offer would be much appreciated.

Dale Busse
NonStop Debugging Tools



--
Unsubscribe info:      http://cygwin.com/ml/#unsubscribe-simple
Problem reports:       http://cygwin.com/problems.html
Documentation:         http://cygwin.com/docs.html
FAQ:                   http://cygwin.com/faq/