2.3.3 Debug log file

The runtest option --debug creates a file showing the output from Expect in debugging mode. The dbg.log file is created in the current directory. The log file shows the string sent to the tool being tested by each send command and the pattern it compares with the tool output by each expect command.

The log messages 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.

Example debug log file 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) }
epect: 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 standard output, and in the detailed log file.