Expect later `expect` statement still tried to be matched against previous `send`

Question

I'm not understanding the runtime behavior of Expect. My goal is to execute some commands, ignore the output so far and then match a send output against an expect expression following. Expect tries to match this expression still against the first send statements which is matching an incorrect result. How can expect be forced to look only into the last send statement?

#!/usr/bin/env expect -f
log_user 0
# for debugging
exp_internal 1
spawn gpshell
expect *
send "establish_context\r"
expect *
send "enable_trace\r"
expect *
send "card_connect\r"
expect *
send "send_apdu -sc 0 -APDU 00a40004023f00\r"
expect *
send "send_apdu -sc 0 -APDU 00a40804022fe2\r"
expect *
send "send_apdu -sc 0 -APDU 00B000000A\r"
expect -indices -re {(?n)<-- ([0-9]+).*$}
set iccid $expect_out(1,string)
puts $iccid
send "card_disconnect\r"
send "release_context\r"
send \x03
exit 0

Debug output:

parent: waiting for sync byte
parent: telling child to go ahead
parent: now unsynchronized from child
spawn: returns {1640670}

expect: does "" (spawn_id exp4) match glob pattern "*"? yes
expect: set expect_out(0,string) ""
expect: set expect_out(spawn_id) "exp4"
expect: set expect_out(buffer) ""
send: sending "establish_context\r" to { exp4 }

expect: does "" (spawn_id exp4) match glob pattern "*"? yes
expect: set expect_out(0,string) ""
expect: set expect_out(spawn_id) "exp4"
expect: set expect_out(buffer) ""
send: sending "enable_trace\r" to { exp4 }

expect: does "" (spawn_id exp4) match glob pattern "*"? yes
expect: set expect_out(0,string) ""
expect: set expect_out(spawn_id) "exp4"
expect: set expect_out(buffer) ""
send: sending "card_connect\r" to { exp4 }

expect: does "" (spawn_id exp4) match glob pattern "*"? yes
expect: set expect_out(0,string) ""
expect: set expect_out(spawn_id) "exp4"
expect: set expect_out(buffer) ""
send: sending "send_apdu -sc 0 -APDU 00a40004023f00\r" to { exp4 }

expect: does "" (spawn_id exp4) match glob pattern "*"? yes
expect: set expect_out(0,string) ""
expect: set expect_out(spawn_id) "exp4"
expect: set expect_out(buffer) ""
send: sending "send_apdu -sc 0 -APDU 00a40804022fe2\r" to { exp4 }

expect: does "" (spawn_id exp4) match glob pattern "*"? yes
expect: set expect_out(0,string) ""
expect: set expect_out(spawn_id) "exp4"
expect: set expect_out(buffer) ""
send: sending "send_apdu -sc 0 -APDU 00B000000A\r" to { exp4 }
Gate keeper glob pattern for '(?n)<-- ([0-9]+).*$' is '<-- *'. Activating booster.

expect: does "" (spawn_id exp4) match regular expression "(?n)<-- ([0-9]+).*$"? Gate "<-- *"? gate=no

expect: does "establish_context\r\nenable_trace\r\ncard_connect\r\nsend_apdu -sc 0 -APDU 00a40004023f00\r\nsend_apdu -sc 0 -APDU 00a40804022fe2\r\nsend_apdu -sc 0 -APDU 00B000000A\r\nestablish_context\r\n" (spawn_id exp4) match regular expression "(?n)<-- ([0-9]+).*$"? Gate "<-- *"? gate=no

expect: does "establish_context\r\nenable_trace\r\ncard_connect\r\nsend_apdu -sc 0 -APDU 00a40004023f00\r\nsend_apdu -sc 0 -APDU 00a40804022fe2\r\nsend_apdu -sc 0 -APDU 00B000000A\r\nestablish_context\r\nenable_trace\r\ncard_connect\r\n" (spawn_id exp4) match regular expression "(?n)<-- ([0-9]+).*$"? Gate "<-- *"? gate=no

expect: does "establish_context\r\nenable_trace\r\ncard_connect\r\nsend_apdu -sc 0 -APDU 00a40004023f00\r\nsend_apdu -sc 0 -APDU 00a40804022fe2\r\nsend_apdu -sc 0 -APDU 00B000000A\r\nestablish_context\r\nenable_trace\r\ncard_connect\r\n* reader name Virtual PCD 00 00\r\n" (spawn_id exp4) match regular expression "(?n)<-- ([0-9]+).*$"? Gate "<-- *"? gate=no

expect: does "establish_context\r\nenable_trace\r\ncard_connect\r\nsend_apdu -sc 0 -APDU 00a40004023f00\r\nsend_apdu -sc 0 -APDU 00a40804022fe2\r\nsend_apdu -sc 0 -APDU 00B000000A\r\nestablish_context\r\nenable_trace\r\ncard_connect\r\n* reader name Virtual PCD 00 00\r\n* reader name Virtual PCD 00 01\r\n" (spawn_id exp4) match regular expression "(?n)<-- ([0-9]+).*$"? Gate "<-- *"? gate=no

expect: does "establish_context\r\nenable_trace\r\ncard_connect\r\nsend_apdu -sc 0 -APDU 00a40004023f00\r\nsend_apdu -sc 0 -APDU 00a40804022fe2\r\nsend_apdu -sc 0 -APDU 00B000000A\r\nestablish_context\r\nenable_trace\r\ncard_connect\r\n* reader name Virtual PCD 00 00\r\n* reader name Virtual PCD 00 01\r\n* reader name OMNIKEY CardMan 5321 00 00\r\n" (spawn_id exp4) match regular expression "(?n)<-- ([0-9]+).*$"? Gate "<-- *"? gate=no

expect: does "establish_context\r\nenable_trace\r\ncard_connect\r\nsend_apdu -sc 0 -APDU 00a40004023f00\r\nsend_apdu -sc 0 -APDU 00a40804022fe2\r\nsend_apdu -sc 0 -APDU 00B000000A\r\nestablish_context\r\nenable_trace\r\ncard_connect\r\n* reader name Virtual PCD 00 00\r\n* reader name Virtual PCD 00 01\r\n* reader name OMNIKEY CardMan 5321 00 00\r\nsend_apdu -sc 0 -APDU 00a40004023f00\r\nCommand --> 00A40004023F00\r\nWrapped command --> 00A40004023F00\r\n" (spawn_id exp4) match regular expression "(?n)<-- ([0-9]+).*$"? Gate "<-- *"? gate=no

expect: does "establish_context\r\nenable_trace\r\ncard_connect\r\nsend_apdu -sc 0 -APDU 00a40004023f00\r\nsend_apdu -sc 0 -APDU 00a40804022fe2\r\nsend_apdu -sc 0 -APDU 00B000000A\r\nestablish_context\r\nenable_trace\r\ncard_connect\r\n* reader name Virtual PCD 00 00\r\n* reader name Virtual PCD 00 01\r\n* reader name OMNIKEY CardMan 5321 00 00\r\nsend_apdu -sc 0 -APDU 00a40004023f00\r\nCommand --> 00A40004023F00\r\nWrapped command --> 00A40004023F00\r\nResponse <-- 62288202782183023F00A50B8001718303078ED08701018A01058B032F060EC60990018083010A8301019000\r\nUnwrapped response <-- 62288202782183023F00A50B8001718303078ED08701018A01058B032F060EC60990018083010A8301019000\r\nsend_APDU() returns 0x80209000 (Success)\r\nsend_apdu -sc 0 -APDU 00a40804022fe2\r\nCommand --> 00A40804022FE2\r\nWrapped command --> 00A40804022FE2\r\n" (spawn_id exp4) match regular expression "(?n)<-- ([0-9]+).*$"? Gate "<-- *"? gate=yes re=yes
expect: set expect_out(0,start) "423"
expect: set expect_out(0,end) "515"
expect: set expect_out(0,string) "<-- 62288202782183023F00A50B8001718303078ED08701018A01058B032F060EC60990018083010A8301019000\r"
expect: set expect_out(1,start) "427"
expect: set expect_out(1,end) "443"
expect: set expect_out(1,string) "62288202782183023"
expect: set expect_out(spawn_id) "exp4"
expect: set expect_out(buffer) "establish_context\r\nenable_trace\r\ncard_connect\r\nsend_apdu -sc 0 -APDU 00a40004023f00\r\nsend_apdu -sc 0 -APDU 00a40804022fe2\r\nsend_apdu -sc 0 -APDU 00B000000A\r\nestablish_context\r\nenable_trace\r\ncard_connect\r\n* reader name Virtual PCD 00 00\r\n* reader name Virtual PCD 00 01\r\n* reader name OMNIKEY CardMan 5321 00 00\r\nsend_apdu -sc 0 -APDU 00a40004023f00\r\nCommand --> 00A40004023F00\r\nWrapped command --> 00A40004023F00\r\nResponse <-- 62288202782183023F00A50B8001718303078ED08701018A01058B032F060EC60990018083010A8301019000\r"
send: sending "card_disconnect\r" to { exp4 }
send: sending "release_context\r" to { exp4 }
send: sending "\u0003" to { exp4 }

The 62288202782183023 is from an earlier command, not from the one after which I have added the expectation.

Answer 1

The typical automation sequence is:

spawn ...
expect something
send "...\r"
expect something
send "...\r"
expect something

... and so on, so that after each command you type, you wait for the spawned process to respond. It allows you to gather up whatever the process outputs, and discard it if you don't care about it.

The first expect after spawn is important. You know at that point that the spawned process is ready to receive a command.

Typically, you're automating some kind of shell. The something that you expect is usually some kind of prompt.