5.7.3 Logging expect internal actions

With the ‘--debug’ option, you can request a log file showing the output from expect itself, running in debugging mode. This file (‘dbg.log’, in the directory where you start runtest) shows each pattern expect considers in analyzing test output.

This file reflects each send command, showing the string sent as input to the tool under test; and each expect command, showing each pattern it compares with the tool output.

The log messages for expect begin with a message of the form

expect: does {tool output} (spawn_id n) match pattern
{expected pattern}?

For every unsuccessful match, expect issues a ‘no’ after this message; if other patterns are specified for the same expect command, they are reflected also, but without the first part of the message (‘expect…match pattern’).

When expect finds a match, the log for the successful match ends with ‘yes’, followed by a record of the expect variables set to describe a successful match. Here is an excerpt from the debugging log for a GDB test:

send: sent {break gdbme.c:34\n} to spawn id 6
expect: does {} (spawn_id 6) match pattern {Breakpoint.*at.* file
 gdbme.c, line 34.*\(gdb\) $}? no
{.*\(gdb\) $}? no
expect: does {} (spawn_id 0) match pattern {<return>}? no
{\(y or n\) }? no
{buffer_full}? no
{virtual}? no
{memory}? no
{exhausted}? no
{Undefined}? no
{command}? no
break gdbme.c:34
Breakpoint 8 at 0x23d8: file gdbme.c, line 34.
(gdb) expect: does {break gdbme.c:34\r\nBreakpoint 8 at 0x23d8:
file gdbme.c, line 34.\r\n(gdb) } (spawn_id 6) match pattern
{Breakpoint.*at.* file gdbme.c, line 34.*\(gdb\) $}? yes
expect: set expect_out(0,start) {18}
expect: set expect_out(0,end) {71}
expect: set expect_out(0,string) {Breakpoint 8 at 0x23d8: file
gdbme.c, line 34.\r\n(gdb) }
expect: set expect_out(spawn_id) {6}
expect: set expect_out(buffer) {break gdbme.c:34\r\nBreakpoint 8
at 0x23d8: file gdbme.c, line 34.\r\n(gdb) }
        PASS:   70      0       breakpoint line number in file

This example exhibits three properties of expect and DejaGnu that might be surprising at first glance:

• Empty output for the first attempted match. The first set of attempted matches shown ran against the output ‘{}’—that is, no output. expect begins attempting to match the patterns supplied immediately; often, the first pass is against incomplete output (or completely before all output, as in this case).
• Interspersed tool output. The beginning of the log entry for the second attempted match may be hard to spot: this is because the prompt ‘(gdb) ’ appears on the same line, just before the ‘expect:’ that marks the beginning of the log entry.
• Fail-safe patterns. Many of the patterns tested are fail-safe patterns provided by GDB testing utilities, to reduce possible indeterminacy. It is useful to anticipate potential variations caused by extreme system conditions (GDB might issue the message ‘virtual memory exhausted’ in rare circumstances), or by changes in the tested program (‘Undefined command’ is the likeliest outcome if the name of a tested command changes).

  The pattern ‘{<return>}’ is a particularly interesting fail-safe to notice; it checks for an unexpected <RET> prompt. This may happen, for example, if the tested tool can filter output through a pager.

  These fail-safe patterns (like the debugging log itself) are primarily useful while developing test scripts. Use the error procedure to make the actions for fail-safe patterns produce messages starting with ‘ERROR’ on the runtest standard output, and in the detailed log file.