Re: Problems with expect and Fedora / Gentoo (URGENT)

From: Don Libes (libes_at_nist.gov)
Date: 09/15/04 

Date: 15 Sep 2004 15:13:58 -0400

Thanks for the trace. It's helpful and I can now narrow it down to
one small section of code. But since I can't reproduce the problem,
I'm going to have to ask you to do a little debugging for me.

I walked through the trace and added comments so the code will make
more sense to you. I've extracted the part that seems relevant below.
For readability, I deleted the many gettimeofday calls.

Sorry for all the detail but some of this is just me thinking aloud to
help myself work on the problem.

Somewhere toward the end of the process, we see pid 11460 (cat)
reading the data file and then spitting it right back out:

> 11460 read(4, "4318\n4319\n4320\n4321\n4322\n4323\n43"..., 4096) = 3410
> 11460 write(1, "4318\n4319\n4320\n4321\n4322\n4323\n43"..., 3410 <unfinished ...>

That looks good. It says <unfinished> because it's not yet finished
before Expect wakes up.

Next we see pid 11459 (Expect) wakeup, read the output from cat, and
echo the same bytes to the tty, then go wait in the event loop:

> 11459 <... select resumed> ) = 1 (in [4])
> 11459 read(4, "4318\r\n4319\r\n4320\r\n4321\r\n4322\r\n43"..., 4096) = 4092
> 11459 write(1, "4318\r\n4319\r\n4320\r\n4321\r\n4322\r\n43"..., 4001) = 4001

Notice Expect read 4092 bytes but wrote 91 short of that. I figure
that's from Tcl doing output buffering.

How did the 3410 from cat become 4092? Well, the end of the data file
contained the numbers from 4318 to 4999 each on a separate line.
That's 682 lines. 5 characters to represent each is 682*5 = 3410. So
that checks. During output, a \r is added to each which requires
682*6 = 4092 bytes. So it all checks. (That sanity check
demonstrates cat is not at fault!)

Next we see the event loop do a quick poll for activity or maybe to
check that it's ok to write more bytes.

> 11459 select(5, [0], [], [0 4], {0, 0}) = 0 (Timeout)
> 11459 read(4, 0x8083ce8, 4096) = -1 EAGAIN (Resource temporarily unavailable)
> 11459 write(1, "\n4985\r\n4986\r\n4987\r\n4988\r\n4989\r\n4"..., 91) = 91

The read failed with EAGAIN but I guess Tcl took the opportunity to
write out the remaining 91 bytes.

Another poll:

> 11459 select(5, [0 4], [], [0 4], {0, 0}) = 0 (Timeout)

No activity, so the event loop now waits:

> 11459 select(5, [0 4], [], [0 4], NULL <unfinished ...>

cat finally gets notification that its write has completed (long ago
actually):

> 11460 <... write resumed> ) = 3410

cat reads the EOF and exits:

> 11460 read(4, "", 4096) = 0
> 11460 close(4) = 0
> 11460 close(1) = 0
> 11460 _exit(0) = ?

Expect wakes up and sees the EOF (represented as EIO but that's ok):

> 11459 <... select resumed> ) = 1 (in [4])
> 11459 read(4, 0x8083ce8, 4096) = -1 EIO (Input/output error)

And now, out of the blue, we see this. Expect writes four bytes.
Huh????

> 11459 write(1, "\000498", 4) = 4

Now Expect shuts down the channel, first by restoring blocking mode
and then closing the file descriptor.

> 11459 fcntl64(4, F_GETFL) = 0x802 (flags O_RDWR|O_NONBLOCK)
> 11459 fcntl64(4, F_SETFL, O_RDWR) = 0
> 11459 fcntl64(4, F_GETFL) = 0x2 (flags O_RDWR)
> 11459 close(4) = 0

So where does that leave us? Expect is doing something very wrong
during the EOF handling of the spawned process. Fortunately, that's a
very small section of code you'll need to watch. Fire up the debugger
and set a breakpoint in exp_inter.c at line 1384. This is where
interact should detect the and begin doing something with it.

Now just single step and wait for that \000498 to pop out. Pay
specific attention to any calls where Expect calls Tcl routines to
write out data. Is Expect really passing those 4 bytes to Tcl? Why?
Or not?

The calling sequence will be the Expect -> Tcl -> Expect's channel
handler. So the problem could arise at any of those three levels.

Don

fryxar@datafull.com writes:

> Hi, here is the strace:
>
> # strace -fo test.dump ./test.exp
> .
> .
> .
> 4997
> 4998
> 4999
> 498
> # cat /tmp/test.dump
> 11459 execve("./test.exp", ["./test.exp"], [/* 30 vars */]) = 0
> 11459 uname({sys="Linux", node="facceso1", ...}) = 0
> 11459 brk(0) = 0x806b000
> 11459 open("/etc/ld.so.preload", O_RDONLY) = -1 ENOENT (No such file
> or directory)
> 11459 mmap2(NULL, 4096, PROT_READ|PROT_WRITE,
> MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x40015000
> 11459 open("/etc/ld.so.cache", O_RDONLY) = 3
> 11459 fstat64(3, {st_mode=S_IFREG|0644, st_size=9583, ...}) = 0
> 11459 mmap2(NULL, 9583, PROT_READ, MAP_PRIVATE, 3, 0) = 0x40016000
> 11459 close(3) = 0
> 11459 open("/usr/lib/libtcl8.3.so", O_RDONLY) = 3
> 11459 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0`\6\1\000"...,
> 512) = 512
> 11459 fstat64(3, {st_mode=S_IFREG|0555, st_size=711762, ...}) = 0
> 11459 mmap2(NULL, 642376, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) =
> 0x40019000
> 11459 mmap2(0x400ad000, 36864, PROT_READ|PROT_WRITE,
> MAP_PRIVATE|MAP_FIXED, 3, 0x93) = 0x400ad000
> 11459 close(3) = 0
> 11459 mprotect(0xbffff000, 4096,
> PROT_READ|PROT_WRITE|PROT_EXEC|PROT_GROWSDOWN) = 0
> 11459 open("/lib/libdl.so.2", O_RDONLY) = 3
> 11459 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0000\34\0"...,
> 512) = 512
> 11459 fstat64(3, {st_mode=S_IFREG|0755, st_size=14177, ...}) = 0
> 11459 mmap2(NULL, 8628, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) =
> 0x400b6000
> 11459 mmap2(0x400b8000, 4096, PROT_READ|PROT_WRITE,
> MAP_PRIVATE|MAP_FIXED, 3, 0x2) = 0x400b8000
> 11459 close(3) = 0
> 11459 open("/lib/libm.so.6", O_RDONLY) = 3
> 11459 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\3404\0"...,
> 512) = 512
> 11459 fstat64(3, {st_mode=S_IFREG|0755, st_size=189312, ...}) = 0
> 11459 mmap2(NULL, 138768, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) =
> 0x400b9000
> 11459 mmap2(0x400da000, 4096, PROT_READ|PROT_WRITE,
> MAP_PRIVATE|MAP_FIXED, 3, 0x20) = 0x400da000
> 11459 close(3) = 0
> 11459 open("/lib/libutil.so.1", O_RDONLY) = 3
> 11459 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\360\r\0"...,
> 512) = 512
> 11459 fstat64(3, {st_mode=S_IFREG|0755, st_size=11074, ...}) = 0
> 11459 mmap2(NULL, 10616, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) =
> 0x400db000
> 11459 mmap2(0x400dd000, 4096, PROT_READ|PROT_WRITE,
> MAP_PRIVATE|MAP_FIXED, 3, 0x1) = 0x400dd000
> 11459 close(3) = 0
> 11459 open("/lib/libc.so.6", O_RDONLY) = 3
> 11459 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0
> ]\1\000"..., 512) = 512
> 11459 fstat64(3, {st_mode=S_IFREG|0755, st_size=1482469, ...}) = 0
> 11459 mmap2(NULL, 1241060, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) =
> 0x400de000
> 11459 mmap2(0x40207000, 16384, PROT_READ|PROT_WRITE,
> MAP_PRIVATE|MAP_FIXED, 3, 0x128) = 0x40207000
> 11459 mmap2(0x4020b000, 8164, PROT_READ|PROT_WRITE,
> MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x4020b000
> 11459 close(3) = 0
> 11459 mmap2(NULL, 4096, PROT_READ|PROT_WRITE,
> MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x4020d000
> 11459 munmap(0x40016000, 9583) = 0
> 11459 open("/dev/urandom", O_RDONLY) = 3
> 11459 read(3, "}p\360\311\315?\322\206O}6rC\273k\27\355\325\325\202\24"...,
> 32) = 32
> 11459 close(3) = 0
> 11459 rt_sigaction(SIGPIPE, {SIG_IGN}, {SIG_DFL}, 8) = 0
> 11459 brk(0) = 0x806b000
> 11459 brk(0x808c000) = 0x808c000
> 11459 brk(0) = 0x808c000
> 11459 uname({sys="Linux", node="facceso1", ...}) = 0
> 11459 open("/usr/lib/tcl8.3/encoding/iso8859-1.enc", O_RDONLY) = 3
> 11459 fcntl64(3, F_SETFD, FD_CLOEXEC) = 0
> 11459 ioctl(3, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbfffef9c) = -1 ENOTTY
> (Inappropriate ioctl for device)
> 11459 read(3, "# Encoding file: iso8859-1, sing"..., 4096) = 1094
> 11459 close(3) = 0
> 11459 access("/usr/lib/tcl8.3/init.tcl", F_OK) = 0
> 11459 stat64("/usr/lib/tcl8.3/init.tcl", {st_mode=S_IFREG|0644,
> st_size=17568, ...}) = 0
> 11459 open("/usr/lib/tcl8.3/init.tcl", O_RDONLY) = 3
> 11459 fcntl64(3, F_SETFD, FD_CLOEXEC) = 0
> 11459 ioctl(3, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbfffea2c) = -1 ENOTTY
> (Inappropriate ioctl for device)
> 11459 read(3, "# init.tcl --\n#\n# Default system"..., 4096) = 4096
> 11459 read(3, "he command was invoked interacti"..., 4096) = 4096
> 11459 read(3, "\"\"\n}\n\n# auto_load --\n# Checks a "..., 4096) =
> 4096
> 11459 read(3, "# count separators and clean the"..., 4096) = 4096
> 11459 read(3, "\n\tappend path \"$windir/system;$w"..., 4096) = 1184
> 11459 read(3, "", 4096) = 0
> 11459 close(3) = 0
> 11459 getpid() = 11459
> 11459 open("/dev/tty", O_RDWR) = 3
> 11459 ioctl(3, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig
> icanon echo ...}) = 0
> 11459 ioctl(3, TIOCGWINSZ, {ws_row=42, ws_col=124, ws_xpixel=0,
> ws_ypixel=0}) = 0
> 11459 ioctl(0, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig
> icanon echo ...}) = 0
> 11459 ioctl(1, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig
> icanon echo ...}) = 0
> 11459 getpid() = 11459
> 11459 ioctl(0, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig
> icanon echo ...}) = 0
> 11459 lseek(0, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek)
> 11459 lseek(1, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek)
> 11459 lseek(2, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek)
> 11459 fcntl64(0, F_GETFL) = 0x8002 (flags
> O_RDWR|O_LARGEFILE)
> 11459 fcntl64(0, F_SETFL, O_RDWR|O_NONBLOCK|O_LARGEFILE) = 0
> 11459 fcntl64(0, F_GETFL) = 0x8802 (flags
> O_RDWR|O_NONBLOCK|O_LARGEFILE)
> 11459 ioctl(2, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig
> icanon echo ...}) = 0
> 11459 fcntl64(2, F_GETFL) = 0x8802 (flags
> O_RDWR|O_NONBLOCK|O_LARGEFILE)
> 11459 fcntl64(2, F_SETFL, O_RDWR|O_NONBLOCK|O_LARGEFILE) = 0
> 11459 fcntl64(2, F_GETFL) = 0x8802 (flags
> O_RDWR|O_NONBLOCK|O_LARGEFILE)
> 11459 fcntl64(3, F_SETFD, FD_CLOEXEC) = 0
> 11459 fcntl64(3, F_GETFL) = 0x2 (flags O_RDWR)
> 11459 fcntl64(3, F_SETFL, O_RDWR|O_NONBLOCK) = 0
> 11459 fcntl64(3, F_GETFL) = 0x802 (flags
> O_RDWR|O_NONBLOCK)
> 11459 rt_sigaction(SIGINT, {0x804fcae, [INT], SA_RESTORER|SA_RESTART,
> 0x40107358}, {SIG_DFL}, 8) = 0
> 11459 rt_sigaction(SIGTERM, {0x804fcae, [TERM],
> SA_RESTORER|SA_RESTART, 0x40107358}, {SIG_DFL}, 8) = 0
> 11459 open("/usr/lib/expect5.42/expect.rc", O_RDONLY) = -1 ENOENT (No
> such file or directory)
> 11459 open("/root/.expect.rc", O_RDONLY) = -1 ENOENT (No such file or
> directory)
> 11459 stat64("./test.exp", {st_mode=S_IFREG|0755, st_size=85, ...}) =
> 0
> 11459 open("./test.exp", O_RDONLY) = 4
> 11459 fcntl64(4, F_SETFD, FD_CLOEXEC) = 0
> 11459 ioctl(4, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbffff49c) = -1 ENOTTY
> (Inappropriate ioctl for device)
> 11459 read(4, "#!/usr/bin/expect --\n\nspawn -noe"..., 4096) = 85
> 11459 read(4, "", 4096) = 0
> 11459 close(4) = 0
> 11459 open("/dev/ptmx", O_RDWR) = 4
> 11459 statfs("/dev/pts", {f_type="DEVPTS_SUPER_MAGIC", f_bsize=4096,
> f_blocks=0, f_bfree=0, f_bavail=0, f_files=0, f_ffree=0, f_fsid={0,
> 0}, f_namelen=255, f_frsize=4096}) = 0
> 11459 ioctl(4, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig
> icanon echo ...}) = 0
> 11459 ioctl(4, TIOCGPTN, [55]) = 0
> 11459 stat64("/dev/pts/55", {st_mode=S_IFCHR|0620,
> st_rdev=makedev(136, 55), ...}) = 0
> 11459 statfs("/dev/pts/55", {f_type="DEVPTS_SUPER_MAGIC",
> f_bsize=4096, f_blocks=0, f_bfree=0, f_bavail=0, f_files=0, f_ffree=0,
> f_fsid={0, 0}, f_namelen=255, f_frsize=4096}) = 0
> 11459 ioctl(4, TIOCSPTLCK, [0]) = 0
> 11459 ioctl(4, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig
> icanon echo ...}) = 0
> 11459 ioctl(4, TIOCGPTN, [55]) = 0
> 11459 stat64("/dev/pts/55", {st_mode=S_IFCHR|0620,
> st_rdev=makedev(136, 55), ...}) = 0
> 11459 open("/dev/pts/55", O_RDWR|O_NOCTTY) = 5
> 11459 ioctl(5, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig
> icanon echo ...}) = 0
> 11459 readlink("/proc/self/fd/5", "/dev/pts/55", 4095) = 11
> 11459 close(5) = 0
> 11459 fcntl64(4, F_SETFD, FD_CLOEXEC) = 0
> 11459 pipe([5, 6]) = 0
> 11459 pipe([7, 8]) = 0
> 11459 pipe([9, 10]) = 0
> 11459 fork() = 11460
> 11459 close(6) = 0
> 11459 close(7) = 0
> 11459 close(10) = 0
> 11459 fcntl64(4, F_SETFD, FD_CLOEXEC) = 0
> 11459 fcntl64(4, F_GETFL) = 0x2 (flags O_RDWR)
> 11459 fcntl64(4, F_SETFL, O_RDWR|O_NONBLOCK) = 0
> 11459 fcntl64(4, F_GETFL) = 0x802 (flags
> O_RDWR|O_NONBLOCK)
> 11459 read(5, <unfinished ...>
> 11460 close(5) = 0
> 11460 close(8) = 0
> 11460 close(9) = 0
> 11460 fcntl64(10, F_SETFD, FD_CLOEXEC) = 0
> 11460 close(3) = 0
> 11460 setsid() = 11460
> 11460 fcntl64(2, F_DUPFD, 3) = 3
> 11460 close(0) = 0
> 11460 close(1) = 0
> 11460 close(2) = 0
> 11460 open("/dev/pts/55", O_RDWR) = 0
> 11460 fcntl64(0, F_DUPFD, 1) = 1
> 11460 fcntl64(0, F_DUPFD, 2) = 2
> 11460 ioctl(0, SNDCTL_TMR_STOP or TCSETSW, {B38400 opost isig icanon
> echo ...}) = 0
> 11460 ioctl(0, TIOCSWINSZ, {ws_row=42, ws_col=124, ws_xpixel=0,
> ws_ypixel=0}) = 0
> 11460 --- SIGWINCH (Window changed) @ 0 (0) ---
> 11460 rt_sigaction(SIGCHLD, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGINT, {SIG_IGN}, {0x804fcae, [INT],
> SA_RESTORER|SA_RESTART, 0x40107358}, 8) = 0
> 11460 rt_sigaction(SIGQUIT, {SIG_IGN}, {SIG_DFL}, 8) = 0
> 11460 rt_sigprocmask(SIG_BLOCK, [CHLD], [RTMIN], 8) = 0
> 11460 fork() = 11461
> 11460 waitpid(11461, <unfinished ...>
> 11461 rt_sigaction(SIGINT, {0x804fcae, [INT], SA_RESTORER|SA_RESTART,
> 0x40107358}, NULL, 8) = 0
> 11461 rt_sigaction(SIGQUIT, {SIG_DFL}, NULL, 8) = 0
> 11461 rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0
> 11461 execve("/bin/sh", ["sh", "-c", "/bin/stty sane < /dev/pts/55"],
> [/* 30 vars */]) = 0
> 11461 uname({sys="Linux", node="facceso1", ...}) = 0
> 11461 brk(0) = 0x80fe000
> 11461 open("/etc/ld.so.preload", O_RDONLY) = -1 ENOENT (No such file
> or directory)
> 11461 mmap2(NULL, 4096, PROT_READ|PROT_WRITE,
> MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x40015000
> 11461 open("/etc/ld.so.cache", O_RDONLY) = 4
> 11461 fstat64(4, {st_mode=S_IFREG|0644, st_size=9583, ...}) = 0
> 11461 mmap2(NULL, 9583, PROT_READ, MAP_PRIVATE, 4, 0) = 0x40016000
> 11461 close(4) = 0
> 11461 open("/lib/libdl.so.2", O_RDONLY) = 4
> 11461 read(4, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0000\34\0"...,
> 512) = 512
> 11461 fstat64(4, {st_mode=S_IFREG|0755, st_size=14177, ...}) = 0
> 11461 mmap2(NULL, 8628, PROT_READ|PROT_EXEC, MAP_PRIVATE, 4, 0) =
> 0x40019000
> 11461 mmap2(0x4001b000, 4096, PROT_READ|PROT_WRITE,
> MAP_PRIVATE|MAP_FIXED, 4, 0x2) = 0x4001b000
> 11461 close(4) = 0
> 11461 open("/lib/libc.so.6", O_RDONLY) = 4
> 11461 read(4, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0
> ]\1\000"..., 512) = 512
> 11461 fstat64(4, {st_mode=S_IFREG|0755, st_size=1482469, ...}) = 0
> 11461 mmap2(NULL, 1241060, PROT_READ|PROT_EXEC, MAP_PRIVATE, 4, 0) =
> 0x4001c000
> 11461 mmap2(0x40145000, 16384, PROT_READ|PROT_WRITE,
> MAP_PRIVATE|MAP_FIXED, 4, 0x128) = 0x40145000
> 11461 mmap2(0x40149000, 8164, PROT_READ|PROT_WRITE,
> MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x40149000
> 11461 close(4) = 0
> 11461 munmap(0x40016000, 9583) = 0
> 11461 open("/dev/urandom", O_RDONLY) = 4
> 11461 read(4, "\345m\226\20~\271\306\247k\221\216\233\240\0\3630^\306"...,
> 32) = 32
> 11461 close(4) = 0
> 11461 rt_sigprocmask(SIG_BLOCK, NULL, [RTMIN], 8) = 0
> 11461 open("/dev/tty", O_RDWR|O_NONBLOCK|O_LARGEFILE) = 4
> 11461 close(4) = 0
> 11461 brk(0) = 0x80fe000
> 11461 brk(0x811f000) = 0x811f000
> 11461 brk(0) = 0x811f000
> 11461 getuid32() = 0
> 11461 getgid32() = 0
> 11461 geteuid32() = 0
> 11461 getegid32() = 0
> 11461 rt_sigprocmask(SIG_BLOCK, NULL, [RTMIN], 8) = 0
> 11461 time(NULL) = 1095251725
> 11461 open("/etc/mtab", O_RDONLY) = 4
> 11461 fstat64(4, {st_mode=S_IFREG|0644, st_size=133, ...}) = 0
> 11461 mmap2(NULL, 4096, PROT_READ|PROT_WRITE,
> MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x40016000
> 11461 read(4, "/dev/hda2 / ext3 rw,noatime 0 0\n"..., 4096) = 133
> 11461 close(4) = 0
> 11461 munmap(0x40016000, 4096) = 0
> 11461 open("/proc/meminfo", O_RDONLY) = 4
> 11461 fstat64(4, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
> 11461 mmap2(NULL, 4096, PROT_READ|PROT_WRITE,
> MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x40016000
> 11461 read(4, "MemTotal: 126524 kB\nMemFre"..., 1024) = 572
> 11461 close(4) = 0
> 11461 munmap(0x40016000, 4096) = 0
> 11461 rt_sigaction(SIGCHLD, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11461 rt_sigaction(SIGCHLD, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11461 rt_sigaction(SIGINT, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11461 rt_sigaction(SIGINT, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11461 rt_sigaction(SIGQUIT, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11461 rt_sigaction(SIGQUIT, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11461 rt_sigprocmask(SIG_BLOCK, NULL, [RTMIN], 8) = 0
> 11461 rt_sigaction(SIGQUIT, {SIG_IGN}, {SIG_DFL}, 8) = 0
> 11461 uname({sys="Linux", node="facceso1", ...}) = 0
> 11461 stat64("/tmp", {st_mode=S_IFDIR|S_ISVTX|0777, st_size=4096,
> ...}) = 0
> 11461 stat64(".", {st_mode=S_IFDIR|S_ISVTX|0777, st_size=4096, ...}) =
> 0
> 11461 getpid() = 11461
> 11461 getppid() = 11460
> 11461 stat64(".", {st_mode=S_IFDIR|S_ISVTX|0777, st_size=4096, ...}) =
> 0
> 11461 stat64("/bin/sh", {st_mode=S_IFREG|0755, st_size=735364, ...}) =
> 0
> 11461 stat64("/bin/sh", {st_mode=S_IFREG|0755, st_size=735364, ...}) =
> 0
> 11461 getpgrp() = 11460
> 11461 rt_sigaction(SIGCHLD, {0x807cb70, [], SA_RESTORER, 0x40045358},
> {SIG_DFL}, 8) = 0
> 11461 rt_sigprocmask(SIG_BLOCK, NULL, [RTMIN], 8) = 0
> 11461 rt_sigprocmask(SIG_BLOCK, NULL, [RTMIN], 8) = 0
> 11461 rt_sigprocmask(SIG_BLOCK, NULL, [RTMIN], 8) = 0
> 11461 rt_sigprocmask(SIG_BLOCK, [INT CHLD], [RTMIN], 8) = 0
> 11461 fork() = 11462
> 11461 rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0
> 11461 rt_sigprocmask(SIG_BLOCK, [CHLD], [RTMIN], 8) = 0
> 11461 rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0
> 11461 rt_sigprocmask(SIG_BLOCK, [CHLD], [RTMIN], 8) = 0
> 11461 rt_sigaction(SIGINT, {0x807ca90, [], SA_RESTORER, 0x40045358},
> {SIG_DFL}, 8) = 0
> 11461 waitpid(-1, <unfinished ...>
> 11462 getpid() = 11462
> 11462 rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0
> 11462 rt_sigaction(SIGTSTP, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11462 rt_sigaction(SIGTTIN, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11462 rt_sigaction(SIGTTOU, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11462 rt_sigaction(SIGINT, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11462 rt_sigaction(SIGQUIT, {SIG_DFL}, {SIG_IGN}, 8) = 0
> 11462 rt_sigaction(SIGCHLD, {SIG_DFL}, {0x807cb70, [], SA_RESTORER,
> 0x40045358}, 8) = 0
> 11462 open("/dev/pts/55", O_RDONLY|O_LARGEFILE) = 4
> 11462 dup2(4, 0) = 0
> 11462 close(4) = 0
> 11462 execve("/bin/stty", ["/bin/stty", "sane"], [/* 28 vars */]) = 0
> 11462 uname({sys="Linux", node="facceso1", ...}) = 0
> 11462 brk(0) = 0x8052000
> 11462 open("/etc/ld.so.preload", O_RDONLY) = -1 ENOENT (No such file
> or directory)
> 11462 mmap2(NULL, 4096, PROT_READ|PROT_WRITE,
> MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x40015000
> 11462 open("/etc/ld.so.cache", O_RDONLY) = 4
> 11462 fstat64(4, {st_mode=S_IFREG|0644, st_size=9583, ...}) = 0
> 11462 mmap2(NULL, 9583, PROT_READ, MAP_PRIVATE, 4, 0) = 0x40016000
> 11462 close(4) = 0
> 11462 open("/lib/libc.so.6", O_RDONLY) = 4
> 11462 read(4, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0
> ]\1\000"..., 512) = 512
> 11462 fstat64(4, {st_mode=S_IFREG|0755, st_size=1482469, ...}) = 0
> 11462 mmap2(NULL, 1241060, PROT_READ|PROT_EXEC, MAP_PRIVATE, 4, 0) =
> 0x40019000
> 11462 mmap2(0x40142000, 16384, PROT_READ|PROT_WRITE,
> MAP_PRIVATE|MAP_FIXED, 4, 0x128) = 0x40142000
> 11462 mmap2(0x40146000, 8164, PROT_READ|PROT_WRITE,
> MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x40146000
> 11462 close(4) = 0
> 11462 munmap(0x40016000, 9583) = 0
> 11462 open("/dev/urandom", O_RDONLY) = 4
> 11462 read(4, "\222Y-\342\262@\6\215\344\257\236vC)`h\33C\310g.\317XO"...,
> 32) = 32
> 11462 close(4) = 0
> 11462 brk(0) = 0x8052000
> 11462 brk(0x8073000) = 0x8073000
> 11462 brk(0) = 0x8073000
> 11462 ioctl(0, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig
> icanon echo ...}) = 0
> 11462 ioctl(0, SNDCTL_TMR_STOP or TCSETSW, {B38400 opost isig icanon
> echo ...}) = 0
> 11462 ioctl(0, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig
> icanon echo ...}) = 0
> 11462 _exit(0) = ?
> 11461 <... waitpid resumed> [WIFEXITED(s) && WEXITSTATUS(s) == 0], 0)
> = 11462
> 11461 rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0
> 11461 --- SIGCHLD (Child exited) @ 0 (0) ---
> 11461 waitpid(-1, 0xbffff57c, WNOHANG) = -1 ECHILD (No child
> processes)
> 11461 sigreturn() = ? (mask now [RTMIN])
> 11461 rt_sigaction(SIGINT, {SIG_DFL}, {0x807ca90, [], SA_RESTORER,
> 0x40045358}, 8) = 0
> 11461 _exit(0) = ?
> 11460 <... waitpid resumed> [WIFEXITED(s) && WEXITSTATUS(s) == 0], 0)
> = 11461
> 11460 rt_sigaction(SIGINT, {0x804fcae, [INT], SA_RESTORER|SA_RESTART,
> 0x40107358}, NULL, 8) = 0
> 11460 rt_sigaction(SIGQUIT, {SIG_DFL}, NULL, 8) = 0
> 11460 rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0
> 11460 --- SIGCHLD (Child exited) @ 0 (0) ---
> 11460 rt_sigaction(SIGCHLD, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 ioctl(0, TIOCSCTTY) = 0
> 11460 rt_sigaction(SIGHUP, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGINT, {SIG_DFL}, {0x804fcae, [INT],
> SA_RESTORER|SA_RESTART, 0x40107358}, 8) = 0
> 11460 rt_sigaction(SIGQUIT, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGILL, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGTRAP, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGABRT, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGBUS, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGFPE, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGKILL, {SIG_DFL}, {SIG_DFL}, 8) = -1 EINVAL
> (Invalid argument)
> 11460 rt_sigaction(SIGUSR1, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGSEGV, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGUSR2, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGPIPE, {SIG_DFL}, {SIG_IGN}, 8) = 0
> 11460 rt_sigaction(SIGALRM, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGTERM, {SIG_DFL}, {0x804fcae, [TERM],
> SA_RESTORER|SA_RESTART, 0x40107358}, 8) = 0
> 11460 rt_sigaction(SIGSTKFLT, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGCHLD, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGCONT, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGSTOP, {SIG_DFL}, {SIG_DFL}, 8) = -1 EINVAL
> (Invalid argument)
> 11460 rt_sigaction(SIGTSTP, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGTTIN, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGTTOU, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGURG, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGXCPU, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGXFSZ, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGVTALRM, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGPROF, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGWINCH, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGIO, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGPWR, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGSYS, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGRTMIN, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGRT_1, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGRT_2, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGRT_3, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGRT_4, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGRT_5, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGRT_6, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGRT_7, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGRT_8, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGRT_9, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGRT_10, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGRT_11, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGRT_12, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGRT_13, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGRT_14, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGRT_15, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGRT_16, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGRT_17, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGRT_18, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGRT_19, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGRT_20, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGRT_21, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGRT_22, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGRT_23, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGRT_24, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGRT_25, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGRT_26, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGRT_27, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGRT_28, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGRT_29, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGRT_30, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGRT_31, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 rt_sigaction(SIGRT_32, {SIG_DFL}, {SIG_DFL}, 8) = 0
> 11460 write(6, " ", 1 <unfinished ...>
> 11459 <... read resumed> " ", 1) = 1
> 11459 write(8, " ", 1) = 1
> 11459 close(5) = 0
> 11459 close(8) = 0
> 11459 read(9, <unfinished ...>
> 11460 <... write resumed> ) = 1
> 11460 close(6) = 0
> 11460 read(7, " ", 1) = 1
> 11460 close(7) = 0
> 11460 execve("/bin/cat", ["cat", "/tmp/test.txt"], [/* 30 vars */]
> <unfinished ...>
> 11459 <... read resumed> "", 4) = 0
> 11459 close(9) = 0
> 11459 ioctl(3, SNDCTL_TMR_STOP or TCSETSW, {B38400 -opost -isig
> -icanon -echo ...}) = 0
> 11459 select(5, [0 4], [], [0 4], NULL <unfinished ...>
> 11460 <... execve resumed> ) = 0
> 11460 uname({sys="Linux", node="facceso1", ...}) = 0
> 11460 brk(0) = 0x804d000
> 11460 open("/etc/ld.so.preload", O_RDONLY) = -1 ENOENT (No such file
> or directory)
> 11460 mmap2(NULL, 4096, PROT_READ|PROT_WRITE,
> MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x40015000
> 11460 open("/etc/ld.so.cache", O_RDONLY) = 4
> 11460 fstat64(4, {st_mode=S_IFREG|0644, st_size=9583, ...}) = 0
> 11460 mmap2(NULL, 9583, PROT_READ, MAP_PRIVATE, 4, 0) = 0x40016000
> 11460 close(4) = 0
> 11460 open("/lib/libc.so.6", O_RDONLY) = 4
> 11460 read(4, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0
> ]\1\000"..., 512) = 512
> 11460 fstat64(4, {st_mode=S_IFREG|0755, st_size=1482469, ...}) = 0
> 11460 mmap2(NULL, 1241060, PROT_READ|PROT_EXEC, MAP_PRIVATE, 4, 0) =
> 0x40019000
> 11460 mmap2(0x40142000, 16384, PROT_READ|PROT_WRITE,
> MAP_PRIVATE|MAP_FIXED, 4, 0x128) = 0x40142000
> 11460 mmap2(0x40146000, 8164, PROT_READ|PROT_WRITE,
> MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x40146000
> 11460 close(4) = 0
> 11460 munmap(0x40016000, 9583) = 0
> 11460 open("/dev/urandom", O_RDONLY) = 4
> 11460 read(4, "k\304+(\323\374\16W\373\2754pp\332(\177\377\'\370\32\250"...,
> 32) = 32
> 11460 close(4) = 0
> 11460 brk(0) = 0x804d000
> 11460 brk(0x806e000) = 0x806e000
> 11460 brk(0) = 0x806e000
> 11460 fstat64(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 55),
> ...}) = 0
> 11460 open("/tmp/test.txt", O_RDONLY|O_LARGEFILE) = 4
> 11460 fstat64(4, {st_mode=S_IFREG|0644, st_size=23890, ...}) = 0
> 11460 read(4, "0\n1\n2\n3\n4\n5\n6\n7\n8\n9\n10\n11\n12\n13\n"...,
> 4096) = 4096
> 11460 write(1, "0\n1\n2\n3\n4\n5\n6\n7\n8\n9\n10\n11\n12\n13\n"...,
> 4096 <unfinished ...>
> 11459 <... select resumed> ) = 1 (in [4])
> 11459 read(4, "0\r\n1\r\n2\r\n3\r\n4\r\n5\r\n6\r\n7\r\n8\r\n9\r\n10"...,
> 4096) = 4095
> 11459 write(1, "0\r\n1\r\n2\r\n3\r\n4\r\n5\r\n6\r\n7\r\n8\r\n9\r\n10"...,
> 4001) = 4001
> 11459 gettimeofday({1095251725, 107469}, {180, 0}) = 0
> 11459 gettimeofday({1095251725, 107554}, {180, 0}) = 0
> 11459 gettimeofday({1095251725, 107643}, {180, 0}) = 0
> 11459 select(5, [0], [], [0 4], {0, 0}) = 0 (Timeout)
> 11459 gettimeofday({1095251725, 108014}, {180, 0}) = 0
> 11459 gettimeofday({1095251725, 108090}, {180, 0}) = 0
> 11459 gettimeofday({1095251725, 108169}, {180, 0}) = 0
> 11459 gettimeofday({1095251725, 108240}, {180, 0}) = 0
> 11459 gettimeofday({1095251725, 108330}, {180, 0}) = 0
> 11459 read(4, 0x8083ce8, 4096) = -1 EAGAIN (Resource
> temporarily unavailable)
> 11459 write(1, "22\r\n823\r\n824\r\n825\r\n826\r\n827\r\n828"..., 94)
> = 94
> 11459 gettimeofday({1095251725, 108807}, {180, 0}) = 0
> 11459 select(5, [0 4], [], [0 4], {0, 0}) = 0 (Timeout)
> 11459 gettimeofday({1095251725, 109176}, {180, 0}) = 0
> 11459 gettimeofday({1095251725, 109251}, {180, 0}) = 0
> 11459 select(5, [0 4], [], [0 4], NULL) = 1 (in [4])
> 11459 read(4, "841\r\n842\r\n843\r\n844\r\n845\r\n846\r\n84"..., 4096)
> = 1042
> 11459 write(1, "841\r\n842\r\n843\r\n844\r\n845\r\n846\r\n84"...,
> 1042) = 1042
> 11459 select(5, [0 4], [], [0 4], NULL <unfinished ...>
> 11460 <... write resumed> ) = 4096
> 11460 read(4, "041\n1042\n1043\n1044\n1045\n1046\n104"..., 4096) =
> 4096
> 11460 write(1, "041\n1042\n1043\n1044\n1045\n1046\n104"..., 4096
> <unfinished ...>
> 11459 <... select resumed> ) = 1 (in [4])
> 11459 read(4, "041\r\n1042\r\n1043\r\n1044\r\n1045\r\n104"..., 4096) =
> 4095
> 11459 write(1, "041\r\n1042\r\n1043\r\n1044\r\n1045\r\n104"..., 4001)
> = 4001
> 11459 gettimeofday({1095251725, 114807}, {180, 0}) = 0
> 11459 gettimeofday({1095251725, 114903}, {180, 0}) = 0
> 11459 gettimeofday({1095251725, 114982}, {180, 0}) = 0
> 11459 select(5, [0], [], [0 4], {0, 0}) = 0 (Timeout)
> 11459 gettimeofday({1095251725, 115330}, {180, 0}) = 0
> 11459 gettimeofday({1095251725, 115406}, {180, 0}) = 0
> 11459 gettimeofday({1095251725, 115480}, {180, 0}) = 0
> 11459 gettimeofday({1095251725, 115551}, {180, 0}) = 0
> 11459 gettimeofday({1095251725, 115634}, {180, 0}) = 0
> 11459 read(4, 0x8083ce8, 4096) = -1 EAGAIN (Resource
> temporarily unavailable)
> 11459 write(1, "1708\r\n1709\r\n1710\r\n1711\r\n1712\r\n17"..., 94) =
> 94
> 11459 gettimeofday({1095251725, 116042}, {180, 0}) = 0
> 11459 select(5, [0 4], [], [0 4], {0, 0}) = 0 (Timeout)
> 11459 gettimeofday({1095251725, 116388}, {180, 0}) = 0
> 11459 gettimeofday({1095251725, 116462}, {180, 0}) = 0
> 11459 select(5, [0 4], [], [0 4], NULL) = 1 (in [4])
> 11459 read(4, "\r\n1724\r\n1725\r\n1726\r\n1727\r\n1728\r\n"..., 4096)
> = 820
> 11459 write(1, "\r\n1724\r\n1725\r\n1726\r\n1727\r\n1728\r\n"..., 820)
> = 820
> 11459 select(5, [0 4], [], [0 4], NULL <unfinished ...>
> 11460 <... write resumed> ) = 4096
> 11460 read(4, "60\n1861\n1862\n1863\n1864\n1865\n1866"..., 4096) =
> 4096
> 11460 write(1, "60\n1861\n1862\n1863\n1864\n1865\n1866"..., 4096
> <unfinished ...>
> 11459 <... select resumed> ) = 1 (in [4])
> 11459 read(4, "60\r\n1861\r\n1862\r\n1863\r\n1864\r\n1865"..., 4096) =
> 4094
> 11459 write(1, "60\r\n1861\r\n1862\r\n1863\r\n1864\r\n1865"..., 4001)
> = 4001
> 11459 gettimeofday({1095251725, 121746}, {180, 0}) = 0
> 11459 gettimeofday({1095251725, 121823}, {180, 0}) = 0
> 11459 gettimeofday({1095251725, 121920}, {180, 0}) = 0
> 11459 select(5, [0], [], [0 4], {0, 0}) = 0 (Timeout)
> 11459 gettimeofday({1095251725, 122268}, {180, 0}) = 0
> 11459 gettimeofday({1095251725, 122343}, {180, 0}) = 0
> 11459 gettimeofday({1095251725, 122418}, {180, 0}) = 0
> 11459 gettimeofday({1095251725, 122489}, {180, 0}) = 0
> 11459 gettimeofday({1095251725, 122572}, {180, 0}) = 0
> 11459 read(4, 0x8083ce8, 4096) = -1 EAGAIN (Resource
> temporarily unavailable)
> 11459 write(1, "527\r\n2528\r\n2529\r\n2530\r\n2531\r\n253"..., 93) =
> 93
> 11459 gettimeofday({1095251725, 122973}, {180, 0}) = 0
> 11459 select(5, [0 4], [], [0 4], {0, 0}) = 0 (Timeout)
> 11459 gettimeofday({1095251725, 123322}, {180, 0}) = 0
> 11459 gettimeofday({1095251725, 123396}, {180, 0}) = 0
> 11459 select(5, [0 4], [], [0 4], NULL) = 1 (in [4])
> 11459 read(4, "\r\n2543\r\n2544\r\n2545\r\n2546\r\n2547\r\n"..., 4096)
> = 821
> 11459 write(1, "\r\n2543\r\n2544\r\n2545\r\n2546\r\n2547\r\n"..., 821)
> = 821
> 11459 select(5, [0 4], [], [0 4], NULL <unfinished ...>
> 11460 <... write resumed> ) = 4096
> 11460 read(4, "9\n2680\n2681\n2682\n2683\n2684\n2685\n"..., 4096) =
> 4096
> 11460 write(1, "9\n2680\n2681\n2682\n2683\n2684\n2685\n"..., 4096
> <unfinished ...>
> 11459 <... select resumed> ) = 1 (in [4])
> 11459 read(4, "9\r\n2680\r\n2681\r\n2682\r\n2683\r\n2684\r"..., 4096)
> = 4095
> 11459 write(1, "9\r\n2680\r\n2681\r\n2682\r\n2683\r\n2684\r"..., 4001)
> = 4001
> 11459 gettimeofday({1095251725, 128550}, {180, 0}) = 0
> 11459 gettimeofday({1095251725, 128626}, {180, 0}) = 0
> 11459 gettimeofday({1095251725, 128703}, {180, 0}) = 0
> 11459 select(5, [0], [], [0 4], {0, 0}) = 0 (Timeout)
> 11459 gettimeofday({1095251725, 129064}, {180, 0}) = 0
> 11459 gettimeofday({1095251725, 129143}, {180, 0}) = 0
> 11459 gettimeofday({1095251725, 129216}, {180, 0}) = 0
> 11459 gettimeofday({1095251725, 129287}, {180, 0}) = 0
> 11459 gettimeofday({1095251725, 129369}, {180, 0}) = 0
> 11459 read(4, 0x8083ce8, 4096) = -1 EAGAIN (Resource
> temporarily unavailable)
> 11459 write(1, "46\r\n3347\r\n3348\r\n3349\r\n3350\r\n3351"..., 94) =
> 94
> 11459 gettimeofday({1095251725, 130075}, {180, 0}) = 0
> 11459 select(5, [0 4], [], [0 4], {0, 0}) = 0 (Timeout)
> 11459 gettimeofday({1095251725, 130425}, {180, 0}) = 0
> 11459 gettimeofday({1095251725, 130499}, {180, 0}) = 0
> 11459 select(5, [0 4], [], [0 4], NULL) = 1 (in [4])
> 11459 read(4, "3362\r\n3363\r\n3364\r\n3365\r\n3366\r\n33"..., 4096) =
> 820
> 11459 write(1, "3362\r\n3363\r\n3364\r\n3365\r\n3366\r\n33"..., 820) =
> 820
> 11459 select(5, [0 4], [], [0 4], NULL <unfinished ...>
> 11460 <... write resumed> ) = 4096
> 11460 read(4, "\n3499\n3500\n3501\n3502\n3503\n3504\n3"..., 4096) =
> 4096
> 11460 write(1, "\n3499\n3500\n3501\n3502\n3503\n3504\n3"..., 4096
> <unfinished ...>
> 11459 <... select resumed> ) = 1 (in [4])
> 11459 read(4, "\r\n3499\r\n3500\r\n3501\r\n3502\r\n3503\r\n"..., 4096)
> = 4095
> 11459 write(1, "\r\n3499\r\n3500\r\n3501\r\n3502\r\n3503\r\n"...,
> 4001) = 4001
> 11459 gettimeofday({1095251725, 135536}, {180, 0}) = 0
> 11459 gettimeofday({1095251725, 135610}, {180, 0}) = 0
> 11459 gettimeofday({1095251725, 135688}, {180, 0}) = 0
> 11459 select(5, [0], [], [0 4], {0, 0}) = 0 (Timeout)
> 11459 gettimeofday({1095251725, 136047}, {180, 0}) = 0
> 11459 gettimeofday({1095251725, 136125}, {180, 0}) = 0
> 11459 gettimeofday({1095251725, 136199}, {180, 0}) = 0
> 11459 gettimeofday({1095251725, 136270}, {180, 0}) = 0
> 11459 gettimeofday({1095251725, 136351}, {180, 0}) = 0
> 11459 read(4, 0x8083ce8, 4096) = -1 EAGAIN (Resource
> temporarily unavailable)
> 11459 write(1, "5\r\n4166\r\n4167\r\n4168\r\n4169\r\n4170\r"..., 94) =
> 94
> 11459 gettimeofday({1095251725, 136700}, {180, 0}) = 0
> 11459 select(5, [0 4], [], [0 4], {0, 0}) = 0 (Timeout)
> 11459 gettimeofday({1095251725, 137308}, {180, 0}) = 0
> 11459 gettimeofday({1095251725, 137383}, {180, 0}) = 0
> 11459 select(5, [0 4], [], [0 4], NULL) = 1 (in [4])
> 11459 read(4, "181\r\n4182\r\n4183\r\n4184\r\n4185\r\n418"..., 4096) =
> 821
> 11459 write(1, "181\r\n4182\r\n4183\r\n4184\r\n4185\r\n418"..., 821) =
> 821
> 11459 select(5, [0 4], [], [0 4], NULL <unfinished ...>
> 11460 <... write resumed> ) = 4096
> 11460 read(4, "4318\n4319\n4320\n4321\n4322\n4323\n43"..., 4096) =
> 3410
> 11460 write(1, "4318\n4319\n4320\n4321\n4322\n4323\n43"..., 3410
> <unfinished ...>
> 11459 <... select resumed> ) = 1 (in [4])
> 11459 read(4, "4318\r\n4319\r\n4320\r\n4321\r\n4322\r\n43"..., 4096) =
> 4092
> 11459 write(1, "4318\r\n4319\r\n4320\r\n4321\r\n4322\r\n43"..., 4001)
> = 4001
> 11459 gettimeofday({1095251725, 142785}, {180, 0}) = 0
> 11459 gettimeofday({1095251725, 142881}, {180, 0}) = 0
> 11459 gettimeofday({1095251725, 142959}, {180, 0}) = 0
> 11459 select(5, [0], [], [0 4], {0, 0}) = 0 (Timeout)
> 11459 gettimeofday({1095251725, 143306}, {180, 0}) = 0
> 11459 gettimeofday({1095251725, 143380}, {180, 0}) = 0
> 11459 gettimeofday({1095251725, 143454}, {180, 0}) = 0
> 11459 gettimeofday({1095251725, 143525}, {180, 0}) = 0
> 11459 gettimeofday({1095251725, 143609}, {180, 0}) = 0
> 11459 read(4, 0x8083ce8, 4096) = -1 EAGAIN (Resource
> temporarily unavailable)
> 11459 write(1, "\n4985\r\n4986\r\n4987\r\n4988\r\n4989\r\n4"..., 91) =
> 91
> 11459 gettimeofday({1095251725, 144185}, {180, 0}) = 0
> 11459 select(5, [0 4], [], [0 4], {0, 0}) = 0 (Timeout)
> 11459 gettimeofday({1095251725, 144528}, {180, 0}) = 0
> 11459 gettimeofday({1095251725, 144602}, {180, 0}) = 0
> 11459 select(5, [0 4], [], [0 4], NULL <unfinished ...>
> 11460 <... write resumed> ) = 3410
> 11460 read(4, "", 4096) = 0
> 11460 close(4) = 0
> 11460 close(1) = 0
> 11460 _exit(0) = ?
> 11459 <... select resumed> ) = 1 (in [4])
> 11459 read(4, 0x8083ce8, 4096) = -1 EIO (Input/output error)
> 11459 write(1, "\000498", 4) = 4
> 11459 fcntl64(4, F_GETFL) = 0x802 (flags
> O_RDWR|O_NONBLOCK)
> 11459 fcntl64(4, F_SETFL, O_RDWR) = 0
> 11459 fcntl64(4, F_GETFL) = 0x2 (flags O_RDWR)
> 11459 close(4) = 0
> 11459 open("/dev/null", O_RDONLY) = 4
> 11459 fcntl64(4, F_SETFD, FD_CLOEXEC) = 0
> 11459 ioctl(3, SNDCTL_TMR_STOP or TCSETSW, {B38400 opost isig icanon
> echo ...}) = 0
> 11459 waitpid(11460, [WIFEXITED(s) && WEXITSTATUS(s) == 0], 0) = 11460
> 11459 --- SIGCHLD (Child exited) @ 0 (0) ---
> 11459 close(4) = 0
> 11459 ioctl(3, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig
> icanon echo ...}) = 0
> 11459 ioctl(3, SNDCTL_TMR_STOP or TCSETSW, {B38400 opost isig icanon
> echo ...}) = 0
> 11459 fcntl64(3, F_GETFL) = 0x802 (flags
> O_RDWR|O_NONBLOCK)
> 11459 fcntl64(3, F_SETFL, O_RDWR) = 0
> 11459 fcntl64(3, F_GETFL) = 0x2 (flags O_RDWR)
> 11459 close(3) = 0
> 11459 open("/dev/null", O_RDONLY) = 3
> 11459 fcntl64(3, F_SETFD, FD_CLOEXEC) = 0
> 11459 fcntl64(2, F_GETFL) = 0x8802 (flags
> O_RDWR|O_NONBLOCK|O_LARGEFILE)
> 11459 fcntl64(2, F_SETFL, O_RDWR|O_LARGEFILE) = 0
> 11459 fcntl64(2, F_GETFL) = 0x8002 (flags
> O_RDWR|O_LARGEFILE)
> 11459 close(2) = 0
> 11459 open("/dev/null", O_RDONLY) = 2
> 11459 fcntl64(2, F_SETFD, FD_CLOEXEC) = 0
> 11459 fcntl64(0, F_GETFL) = 0x8002 (flags
> O_RDWR|O_LARGEFILE)
> 11459 fcntl64(0, F_SETFL, O_RDWR|O_LARGEFILE) = 0
> 11459 fcntl64(0, F_GETFL) = 0x8002 (flags
> O_RDWR|O_LARGEFILE)
> 11459 close(0) = 0
> 11459 close(1) = 0
> 11459 open("/dev/null", O_RDONLY) = 0
> 11459 fcntl64(0, F_SETFD, FD_CLOEXEC) = 0
> 11459 fcntl64(3, F_GETFL) = 0 (flags O_RDONLY)
> 11459 fcntl64(3, F_SETFL, O_RDONLY) = 0
> 11459 fcntl64(3, F_GETFL) = 0 (flags O_RDONLY)
> 11459 close(3) = 0
> 11459 fcntl64(2, F_GETFL) = 0 (flags O_RDONLY)
> 11459 fcntl64(2, F_SETFL, O_RDONLY) = 0
> 11459 fcntl64(2, F_GETFL) = 0 (flags O_RDONLY)
> 11459 close(2) = 0
> 11459 fcntl64(2, F_GETFL) = -1 EBADF (Bad file
> descriptor)
> 11459 fcntl64(2, F_SETFL,
> O_NONBLOCK|O_SYNC|O_ASYNC|O_DIRECT|O_LARGEFILE|O_DIRECTORY|O_NOFOLLOW|0xfffc0000)
> = -1 EBADF (Bad file descriptor)
> 11459 fcntl64(1, F_GETFL) = -1 EBADF (Bad file
> descriptor)
> 11459 fcntl64(1, F_SETFL,
> O_NONBLOCK|O_SYNC|O_ASYNC|O_DIRECT|O_LARGEFILE|O_DIRECTORY|O_NOFOLLOW|0xfffc0000)
> = -1 EBADF (Bad file descriptor)
> 11459 fcntl64(0, F_GETFL) = 0 (flags O_RDONLY)
> 11459 fcntl64(0, F_SETFL, O_RDONLY) = 0
> 11459 fcntl64(0, F_GETFL) = 0 (flags O_RDONLY)
> 11459 fcntl64(0, F_GETFL) = 0 (flags O_RDONLY)
> 11459 fcntl64(0, F_SETFL, O_RDONLY) = 0
> 11459 fcntl64(0, F_GETFL) = 0 (flags O_RDONLY)
> 11459 close(0) = 0
> 11459 _exit(0) = ?
>
>
>
>
> Don Libes <libes@nist.gov> wrote in message news:<s6afz64loj8.fsf@peace.mel.nist.gov>...
> > Next step: Please provide a system call trace.
> >
> > Don
> >
> > fryxar@datafull.com writes:
> >
> > > Hi! I test it in a Gentoo Server, and in a Fedora Core 1 Server, and
> > > both have the same problem. Here I send you the programs versions:
> > >
> > > tcl 8.3.4
> > > glibc 2.3.3
> > > expect 5.42.1 (patch with "Tcl_Flush(esPtr->channel);" in
> > > exp_command.c file)
> > >
> > > Ths!
> > >
> > > Don Libes <libes@nist.gov> wrote in message news:<s6an00mx8nk.fsf@peace.mel.nist.gov>...
> > > > Hmm. I can't reproduce this. It always works fine for me. Are you
> > > > sure you backed out that previous patch? Let's just make sure we're
> > > > on the same page. Here's the script I'm using:
> > > >
> > > > spawn -noecho cat test.txt
> > > > interact -o -nobuffer
> > > >
> > > > Don
> > > >
> > > >
> > > >
> > > >
> > > > fryxar@datafull.com writes:
> > > >
> > > > > I'm sorry, but still it does not work. With the same scripts:
> > > > >
> > > > > ./test.exp
> > > > > 1
> > > > > 2
> > > > > 3
> > > > > 4
> > > > > .
> > > > > .
> > > > > .
> > > > > .
> > > > > 4984
> > > > > 4985
> > > > > 4986
> > > > > 4987
> > > > > 4988
> > > > > 4989
> > > > > 4990
> > > > > 4991
> > > > > 4992
> > > > > 4993
> > > > > 4994
> > > > > 4995
> > > > > 4996
> > > > > 4997
> > > > > 4998
> > > > > 4999
> > > > > 498 <- Nooo
> > > > >
> > > > > It show always the last line. Thanks!
> > > > >
> > > > > FP
> > > > >
> > > > > Don Libes <libes@nist.gov> wrote in message news:<s6awtztybed.fsf@peace.mel.nist.gov>...
> > > > > > Weird. But I have a different solution for you to try. First, back
> > > > > > out the patch you just did. Then do this patch:
> > > > > >
> > > > > > *** exp_command.c~ Mon Aug 16 19:48:45 2004
> > > > > > --- exp_command.c Fri Aug 20 13:18:01 2004
> > > > > > ***************
> > > > > > *** 326,331 ****
> > > > > > --- 326,337 ----
> > > > > > /* surprised finding stdio or /dev/tty nonblocking */
> > > > > > (void) Tcl_SetChannelOption(interp,esPtr->channel,"-blocking","on");
> > > > > >
> > > > > > + /* Since we're closing the channel, not Tcl, we need to get Tcl's
> > > > > > + buffers flushed. Because the channel was nonblocking, EAGAINs
> > > > > > + could leave things buffered. They need to be synchronously
> > > > > > + written now! */
> > > > > > + Tcl_Flush(esPtr->channel);
> > > > > > +
> > > > > > /*
> > > > > > * Ignore close errors from ptys. Ptys on some systems return errors for
> > > > > > * no evident reason. Anyway, receiving an error upon pty-close doesn't
> > > > > >
> > > > > >
> > > > > > fryxar@datafull.com writes:
> > > > > >
> > > > > > > Hi! Now it works better :-)
> > > > > > >
> > > > > > > I have seen only one problem, using the same script, there are some
> > > > > > > lines that are shown twice
> > > > > > >
> > > > > > > >/tmp/test.txt; i=0; while [ $i -lt 5000 ] ; do echo $i; let i=$i+1;
> > > > > > > done >>/tmp/test.txt
> > > > > > >
> > > > > > > cat <<EOF >test.exp
> > > > > > > #!/usr/bin/expect --
> > > > > > >
> > > > > > > spawn -noecho cat /tmp/test.txt
> > > > > > >
> > > > > > > interact -o -nobuffer;
> > > > > > >
> > > > > > > wait
> > > > > > > EOF
> > > > > > >
> > > > > > > cd /tmp; chmod 755 test.exp; ./test.exp
> > > > > > > 1
> > > > > > > 2
> > > > > > > 3
> > > > > > > 4
> > > > > > > 5
> > > > > > > 6
> > > > > > > .
> > > > > > > .
> > > > > > > .
> > > > > > > 4962
> > > > > > > 4963
> > > > > > > 4964
> > > > > > > 4965
> > > > > > > 4966
> > > > > > > 4967
> > > > > > > 4968
> > > > > > > 4969
> > > > > > > 4970
> > > > > > > 4971
> > > > > > > 4972
> > > > > > > 4973
> > > > > > > 4974
> > > > > > > 4975
> > > > > > > 4976
> > > > > > > 4977
> > > > > > > 4978
> > > > > > > 4979
> > > > > > > 4980
> > > > > > > 4981
> > > > > > > 4982
> > > > > > > 4983
> > > > > > > 4984
> > > > > > > 4985
> > > > > > > 4986
> > > > > > > 4987
> > > > > > > 4988
> > > > > > > 4989
> > > > > > > 4990
> > > > > > > 4991
> > > > > > > 4992
> > > > > > > 4993
> > > > > > > 4994
> > > > > > > 4995
> > > > > > > 4996
> > > > > > > 4997
> > > > > > > 4998
> > > > > > > 4999
> > > > > > > 84 <- Here it's the problem
> > > > > > > 4985
> > > > > > > 4986
> > > > > > > 4987
> > > > > > > 4988
> > > > > > > 4989
> > > > > > > 4990
> > > > > > > 4991
> > > > > > > 4992
> > > > > > > 4993
> > > > > > > 4994
> > > > > > > 4995
> > > > > > > 4996
> > > > > > > 4997
> > > > > > > 4998
> > > > > > > 4999
> > > > > > >
> > > > > > >
> > > > > > > Don Libes <libes@nist.gov> wrote in message news:<s6azn4sxioz.fsf@peace.mel.nist.gov>...
> > > > > > > > I think I figured out the problem. Do this patch and recompile:
> > > > > > > >
> > > > > > > > *** /tmp/expect-5.42/exp_chan.c Tue Jul 6 17:24:53 2004
> > > > > > > > --- exp_chan.c Wed Aug 18 16:46:27 2004
> > > > > > > > ***************
> > > > > > > > *** 260,265 ****
> > > > > > > > --- 260,266 ----
> > > > > > > > sleep(1);
> > > > > > > > expDiagLogU("write() failed to write anything - will sleep(1) and retry...\n");
> > > > > > > > } else if (written < 0) {
> > > > > > > > + if (errno == EAGAIN) continue;
> > > > > > > > *errorCodePtr = errno;
> > > > > > > > return -1;
> > > > > > > > }
> > > > > > > >
> > > > > > > >
> > > > > > > > Don
> > > > > > > >
> > > > > > > >
> > > > > > > > fryxar@datafull.com writes:
> > > > > > > >
> > > > > > > > > It works worse with expect 5.42.1!! I make this test:
> > > > > > > > >
> > > > > > > > > >/tmp/test.txt; i=0; while [ $i -lt 5000 ] ; do echo $i; let i=$i+1;
> > > > > > > > > done >>/tmp/test.txt
> > > > > > > > >
> > > > > > > > > and then:
> > > > > > > > >
> > > > > > > > > cat <<EOF >/tmp/test.sh
> > > > > > > > > #!/bin/bash
> > > > > > > > >
> > > > > > > > > echo "Press ENTER"
> > > > > > > > > while read i
> > > > > > > > > do
> > > > > > > > > cat /tmp/test.txt
> > > > > > > > > echo "Press ENTER"
> > > > > > > > > done
> > > > > > > > > EOF
> > > > > > > > >
> > > > > > > > > cat <<EOF >/tmp/test.exp
> > > > > > > > > #!/usr/bin/expect
> > > > > > > > >
> > > > > > > > > spawn -noecho /tmp/test.sh;
> > > > > > > > >
> > > > > > > > > interact -o -nobuffer;
> > > > > > > > > EOF
> > > > > > > > >
> > > > > > > > > and then:
> > > > > > > > > cd /tmp
> > > > > > > > > chmod 755 test.sh test.exp
> > > > > > > > > ./test.exp
> > > > > > > > >
> > > > > > > > > also this simple script does not work!
> > > > > > > > >
> > > > > > > > > #!/usr/bin/expect --
> > > > > > > > >
> > > > > > > > > spawn -noecho cat /tmp/test.txt
> > > > > > > > >
> > > > > > > > > interact -o -nobuffer;
> > > > > > > > >
> > > > > > > > >
> > > > > > > > > Don Libes <libes@nist.gov> wrote in message news:<s6ad61xpleo.fsf@peace.mel.nist.gov>...
> > > > > > > > > > If it outright hangs, it sounds like the problem fixed in the latest
> > > > > > > > > > release (5.42) of Expect.
> > > > > > > > > >
> > > > > > > > > > Don
> > > > > > > > > >
> > > > > > > > > > fryxar@datafull.com writes:
> > > > > > > > > >
> > > > > > > > > > > I've problems with expect, running a simple script in a Fedora server.
> > > > > > > > > > > The same script, running in a Redhat 8 with the same version of
> > > > > > > > > > > expect, works fine. Also I run it in a Gentoo servers, and it doesn't
> > > > > > > > > > > work.
> > > > > > > > > > >
> > > > > > > > > > > This is the script:
> > > > > > > > > > >
> > > > > > > > > > > cat <<EOF >/tmp/test.sh
> > > > > > > > > > > #!/bin/bash
> > > > > > > > > > >
> > > > > > > > > > > echo "Press ENTER"
> > > > > > > > > > > while read i
> > > > > > > > > > > do
> > > > > > > > > > > cat /etc/termcap # A long long file
> > > > > > > > > > > echo "Press ENTER"
> > > > > > > > > > > done
> > > > > > > > > > > EOF
> > > > > > > > > > >
> > > > > > > > > > > cat <<EOF >/tmp/test.exp
> > > > > > > > > > > #!/usr/bin/expect
> > > > > > > > > > >
> > > > > > > > > > > spawn -noecho /tmp/test.sh;
> > > > > > > > > > >
> > > > > > > > > > > interact -o -nobuffer;
> > > > > > > > > > > EOF
> > > > > > > > > > >
> > > > > > > > > > > and then:
> > > > > > > > > > > cd /tmp
> > > > > > > > > > > chmod 755 test.sh test.exp
> > > > > > > > > > > ./test.exp
> > > > > > > > > > > # Press enter and wait
> > > > > > > > > > >
> > > > > > > > > > > The script print the file /etc/termcap, but truncate the end of the
> > > > > > > > > > > file. Is this a bug?
> > > > > > > > > > >
> > > > > > > > > > > Tested versions with problems:
> > > > > > > > > > >
> > > > > > > > > > > kernel: 2.6.7, 2.4.22
> > > > > > > > > > > expect: 5.37.1, 5.39, 5.41
> > > > > > > > > > > glibc: 2.3.2-101, 2.3.3.20040420

Relevant Pages