Tcl Source Code

I've never logged a ticket here.  Apologies if I get something wrong.

We initially noticed this behavior in expect scripts that were getting data from commands run on remote systems via ssh, but I've been able to duplicate the behavior in very simple expect scripts that simply spawn a process that uses cat to output a file.

The behavior is somewhat unpredictable but my tests reproduce it much more often then not.  What happens is that within an expect block, only in cases where the expect block does pattern matching of any kind, an eof can occur before all the data is output by the spawned command, thus truncating the output.

I cannot reproduce this on an older CentOS 5 system running tcl-8.4.13 (and expect-5.43.0-8).  I can however reproduce it on any system I've tried using tcl 8.5, including CentOS 6 (tcl-8.5.7-6.el6.x86_64, expect-5.44.1.15-4.el6.x86_64) and on an x86 Gentoo system (dev-lang/tcl-8.5.13-r1 and dev-tcltk/expect-5.44.1.15).

As mentioned above, this only occurs if the expect block has patterns in addition to the eof.  I've pasted a test script below that spawns "cat ./in.txt".  I've been testing with that using:

expect test.expect > out.txt

...and then...

diff -w in.txt out.txt

...which will show that the output was truncated.  I can reproduce this on files as small as 1000 lines and around 40-50k, with no text that would match any of the patters, and it appears that it's more likely to occur if match_max is reduced.

Here is the test script.  Note that some the original patterns have been left in, but don't actually need to match any text:

set timeout 30

proc exitspawnstat args {
   catch wait result
   set rtn [lindex $result 2]
   if { !$rtn } {
      set rtn [lindex $result 3]
   }
   exit $rtn
}

log_user 1
spawn -noecho cat ./in.txt
expect {
   eof {
      exitspawnstat
   }
   timeout {
      log_user 1
      send_user "Timeout.\n"
      exit 253
   }
   -nocase -re "password:" { 
      exp_continue
   }
   "(yes/no)? " { 
      exp_continue
   }
   -nocase -re "Enter passphrase" {
      exp_continue
   }
   "testing-sudo-passwd:" {
      exp_continue
   }
}

Unfortunately for you, this ticket system
is for bugs in Tcl, not bugs in Expect.

I hate to say it, but while I clearly had issues with what I was doing in expect, even with that corrected there still appear cases, though rare and difficult to reproduce, where expect is getting premature EOFs somehow, at least when running commands via ssh.

I've tried everything I can for hours on end to reproduce any such EOFs running commands via ssh outside of expect and simply can't do it.  It's rare even within expect, but does occasionally occur (with the exact same code and command that may succeed most of the time), and when it does it's WAY more significant than loosing, for example, an expect buffer...often loosing a full third of an xml file for example.

Like I said, so far at least, I've only seen this with ssh, for example, when spawning something like:

spawn -noecho ssh user@host "cat /some/file/path"

I know that's not much to go on, but there clearly seems to be something going on there.

As was implied by my last comment, it's clear that this was a misunderstanding on my part regarding the expect buffer, log_user, and eof functionality...so this issue can be closed.  Hopefully my waste of space here will save someone else the heartache ;).  Thanks to makr and all who assisted!

Oh man...makr, you may have saved me big time on this one.

I had read all that about the full_buffer etc.  Here's what had me confused:  As you can see in my example, I was relying on "log_user 1" to send the output of the spawned process.  What confused me about what I'd seen regarding full_buffer is that there was no question that with large output, I was likely getting full buffers maybe hundreds of times...however the text was in fact getting output by the script based on log_user 1.  Apparently however, relying on that is a mistake, as it can get tripped up by the last full buffer, loosing the end of the output.

I just tested the following change: a) leaving log_user at 0, b) adding a full_buffer that does "puts -nonewline $expect_out(buffer)", and c) adding that same puts statement to the eof block before exiting.  As far as I can tell so far, that works perfectly.

Thanks so much for that.  Wish I'd looked into it more carefully before.  Here's the working test script:

set timeout 30

proc exitspawnstat args {
   catch wait result
   set rtn [lindex $result 2]
   if { !$rtn } {
      set rtn [lindex $result 3]
   }
   exit $rtn
}

log_user 0
set stty_init raw
spawn -noecho cat ./in.txt
expect {
   eof {
      puts -nonewline $expect_out(buffer)
      exitspawnstat
   }
   full_buffer {
      puts -nonewline $expect_out(buffer)
      exp_continue
   }
   timeout {
      log_user 1
      send_user "Timeout.\n"
      exit 253
   }
   -nocase -re "password:" { 
      exp_continue
   }
   "(yes/no)? " { 
      exp_continue
   }
   -nocase -re "Enter passphrase" {
      exp_continue
   }
   "testing-sudo-passwd:" {
      exp_continue
   }
}

I'd suggest to read through Expect's man page (again), e.g. at http://docs.activestate.com/activetcl/8.5/expect/expect.1.html

Where it explains the expect command it says that Expect discards any unmatched buffer, once it grows beyond match_max (default 2000 bytes). This might be the case here.

Do as suggested there and add a full_buffer to your patlist and puts $expect_out(buffer) in its body. That might be enough already. Or you have to dump the buffer one more time in the eof body.

Just suggestions that come from my fainting memory ...

-- makr

The closest thing I can think of to an expect-free test would be to simply use open to open a pipe to "cat filename", and to read from it, and output that data until eof.  Nothing like that, even with some pattern matching added to more closely resemble the other test, seems to loose any data.

I'd imagine that any test like that doesn't resemble what's going on in expect too much, especially since expect is creating a tty and getting output from that etc.  It does seem very unlikely that the Tcl implementation of EOF is in any way broken.  If this is in fact an issue with expect, is that maintained somewhere other than here?

I'll be glad to do anything I can to help with this one, as it's a pretty significant issue for me.  That would even include debugging if need be.  I am a c programmer, though I've been away from that for some time.

Thanks for responding.

"[package require Expect]"

Your second demonstration is still using the
Expect package, so suspicions that the reported
issue may be rooted in Expect, and not in Tcl
are still active.

Below I've pasted a Tcl script that reproduces the issue.  While it's not an expect script, it's still using the Expect package.  I'm not actually clear as to how to even try a similar test with no involvement of Expect at all, as this seems to be related to the EOF from a spawned external process.  Is that even doable in Tcl with anything other than spawn/expect?

Anyway, here's a Tcl script version of the above test, which again, duplicated the issue using "tclsh test.tcl > out.txt":

package require Expect
set timeout 30

proc exitspawnstat args {
   catch wait result
   set rtn [lindex $result 2]
   if { !$rtn } {
      set rtn [lindex $result 3]
   }
   exit $rtn
}

exp_log_user 1
spawn -noecho cat ./in.txt
expect {
	eof {
		exitspawnstat
	}
	timeout {
		exp_log_user 1
		exp_send_user "Timeout.\n"
		exit 253
	}
	-nocase -re "password:" { 
		exp_continue
	}
	"(yes/no)? " { 
		exp_continue
	}
	-nocase -re "Enter passphrase" {
		exp_continue
	}
	"testing-sudo-passwd:" {
		exp_continue
	}
}

I've avoided looking into this because of
the involvement of expect.

Can you determine whether the trouble is in
Tcl or in Expect?

UPDATE: While I've still not been able to reproduce this on older systems with Tcl 8.4, that may just be a random function of the overall speed of those systems, as I am in fact able to reproduce it running a Tlc script with a static version of dqkit from here:

http://sourceforge.net/projects/dqsoftware/files/dqkit/8.4.13-build1/