Expect script, working for years, behaves unexpectedly with new Expect version

Question

I recently migrated from a FreeBSD 4.x server to a FreeBSD 8.0 server. I am now using expect-5.43.0_3. I don't remember what the old version of expect is, and I can't quickly check, because the hard drive on the old system crashed within minutes of finishing the migration! (WHEW!)

Anyway, I have an expect script that creates a zipped tar file and transfers it via FTP each night. This script has been running successfully for YEARS. Suddenly, since the migration/upgrade, it is not working correctly, and I've stared at it and fiddled with it for DAYS without being able to fix it. I want to ensure that each FTP command has completed successfully before moving on to the next one, because the next steps include deleting selected older versions of the file on the remote server, and I don't want to be doing DELETIONS if the TRANSFERS are not working right.

So - this part of the script still works:

...

spawn ftp $ftpmode $ftphost
expect timeout {puts "\nftp connection timeout(implicit)\n"; exit 3}
"timed out" {puts "\nftp connection timeout(explicit)\n"; exit 3} 530 {puts "Login failure!"; exit 3 } "\n230"
expect timeout {puts "\nftp command prompt timeout before progress command\n"; exit 8} "ftp> "
send "progress off\r"
expect timeout {puts "\nftp command prompt timeout before hash command \n"; exit 9} "ftp> "
send "hash 32768\r"
expect timeout {puts "\nftp command timeout";exit 5} "ftp> "

# For each archive file we find (this will catch us up if we've
# been unable to transmit for a few days), send and delete
foreach archive [glob -nocomplain ${archivestem}*$archiveext] {
    send "put $archive\r"
    expect "ftp> " {puts "ftp unexpected prompt 1"; exit 3} timeout {puts "ftp put timeout\n";exit 3} "\n150"

... Here's the dialogue stream that corresponds to the execution of the above:

230 User XXXXXXX logged in.
Remote system type is UNIX.
Using binary mode to transfer files.
ftp> progress off
Progress bar off.
ftp> hash 32768
Hash mark printing on (32768 bytes/hash mark).
ftp> put crewsched-alldump-2010-02-27.tgz
local: crewsched-alldump-2010-02-27.tgz remote: crewsched-
alldump-2010-02-27.tgz
227 Entering Passive Mode (141,224,159,31,30,167)
150 Opening BINARY mode data connection for .
#####################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################
226 Transfer complete.
21689518 bytes sent in 01:15 (280.27 KB/s)

(Note - the hash marks allow me to use a low timeout value and quickly detect if the script is hung)

So far, so good! Everything still working the way it has for the last SIX YEARS, but the next line fails with "ftp unexpected prompt 2", even though the string it is looking for, "\n226" is CLEARLY in the dialogue stream

    expect \# exp_continue "ftp> " {puts "ftp unexpected prompt 2"; exit 3} timeout {puts "ftp put timeout\n";exit 3} "\n226"

Note that there was, very CLEARLY, a "\n226" in the dialogue stream BEFORE the "ftp> ", yet I consistently get "ftp unexpected prompt 2". I tried changing it to "Transfer" or "complete" but it still had the same effect. Right now, I am running the script WITHOUT the check for successful completion, but clearly, I am not satisfied with that, and it is an accident waiting to happen, as the following steps delete selected older files, which I do not want to do if these files were not transferred successfully, which test I currently DO NOT HAVE.

I presume that something has changed with the input stream buffering / handling and that I need to change that so that it "sees" the "\n226" or "Transfer" or "complete" before it "sees" the "ftp> " string, but why? And, for that matter, how? :)

Answer 1

This may be a buffering issue and changing the order of the items in the expect statement may help.

Remember that by default you're specifying "glob" patterns and that those patterns are being compared to buffers of data internally in Expect, not on a strictly character by character basis. Suppose the buffer happened to contain this fragment of the input stream:

######
226 Transfer complete.
21689518 bytes sent in 01:15 (280.27 KB/s)
ftp>

This matches both the glob pattern "ftp>" and the pattern "\n226" and since the former appears first in the expect statement that action will be executed.