Expect script is missing last few lines

[Sar Adde]

I have an expect script that looks for a character pattern to determine completion of an event/test.
I always see the pattern on screen ( minicom serial ), but expect sometimes misses it.
My expect code snippet is like this :

expect {
"done" {
puts "Success"
}
timeout {
puts "timedout"
}
}

I see "timedout" sometimes, but when I manually look at the minicom screen which expect is parsing I see "done" as part of screen output.

Basically problem is "done" string is present on minicom screen, but expect misses it.

Incidentally, this missing is happening to last part of screen content.

[Les Cargill]

I mean no bad reflection on expect, but this is exactly what
inspired me to stop using it and go direct to Tcl serial
ports and sockets, using 'fconfigure' and fileevent handlers.

I can't recall how to configure line discipline in expect, and
Google is no help.

--
Les Cargill

[Sar Adde]

Hi Les,

But I can't go away from expect now. I saw some posts by Dave Harper, and Bruce in this regard, looks like they might have some solution.

http://www.rhinocerus.net/forum/lang-tcl/49379-questions-about-expect-buffers-operation.html

What do you mean by "configure line discipline" exactly.

One more symptom of this problem is that it happens at random, which is making my script unreliable.

Thanks for your help.

[Uwe Klein]

if timeout happens before done is seen expect falls through.

either extend the timeout:
set timeout 10 ;# or another higher value

expect {
"done" {
puts "Success"
}
timeout {
puts "timedout"

# or reenter the expecting loop:
exp_continue
}
}

what happens?

uwe

[Sar Adde]

Actually timeout is pretty large already. I added timeout so that I can exit from expect.
I will give the time line :
Time X seconds : "Done" string is seen on the console.
Time X seconds : I expect to see "success", but unfortunately I don't.
Time X+10 seconds : I see "timedout"

Because I set a timeout value of 10 before I start this piece of code.

Summary is :
Timeout is set high, problem is expect is not seeing the "done" pattern.

Like I said before, this pattern is the last line that is printed.

[Bezoar]

How much data are you matching on? Expect does have a 10000 byte limit
to its buffer. To deal with that Expect provides another target
"full_buffer" along with "timeout" and "eof" to catch when it input
buffer has filled up. If you dont catch that you may clip off what you
are looking for. The following is an example that you can use to
show yourself the problem and the solution. In the snippet, we are
spawning the find command to find all the files under the entire
directory tree from the current working directory. Since it is not an
interactive command we simply wait for the eof.
If you do not have a full_buffer target then the expect_out(buffer)
will fill to 10000 and expect will happily run to eof ignoring any
subsequent
data from the spawned process and finally hit eof and exit. Where upon
only the first 10000 bytes are printed and you're there to ponder why
your file list is short. To solve this problem, uset the full_buffer
target ( as shown) to buffer away the output in your own buffer and
allow expect to start fresh. When you write expect scripts always use
a format like in the snippet below. Always have a eof, timeout and
full_buffer target and handle appropriately.

set pid [spawn find $env(HOME) -type f ]
set sid $spawn_id;
set bad 0;
set done 0;
exp_internal 0; # set to one for extensive debug
log_user 0; # set to one to watch action
set output "" ; # EXTERNAL BUFFER
expect {
-i $sid
timeout {
puts "timeout"
exec kill -9 $pid
set bad 1
exp_continue;
}
full_buffer {

append output "FB:\n$expect_out(buffer)";
exp_continue;
}
eof {
append output "EOF:\n$expect_out(buffer)";
set done 1 ;
}
}
set exitstatus [ exp_wait -i $sid ];
catch { exp_close -i $sid };
puts $output

[Uwe Klein]

is that expect on win or unix?

Can you dump the output?
maybe the "Done" string is not consecutive but
interspersed with cursor commands ?

uwe

[Sar Adde]

Uwe and Bezoar,

Thanks for the suggestions you have.

My platform is Ubuntu.

There are 2 situations that I see.
Case 1 :
========
Here I am looking for a pattern "Done executing".

I looked at the output when problem happens. It looks like this :

[1;1H [M [79;1H [L [80;64H [0m [10m [7m Offline [79;11H [0m [10m Done execu [80;64H [0m [10m [7m Online 00:00 [79;23H [0m [10mting testcases."

My actual search pattern is "Done executing" and it is interspread by minicom control characters.
1. Can you please tell me how to avoid minicom cursor control sequences from appearing, is there a config on minicom or some stty setting that can avoid it.

2. In the above case we see "Done execu" string occur, then it got mixed with control characters. Problem is these control characters can come in after lets say "Don". This means I will not be able to define a pattern that will match deterministically. Is there a good way to define pattern in this case.

Case 2:
=======
Here I am looking for a pattern "/ #".
In this case, the pattern ("/ #") is properly seen, but still expect misses it.
I looked at the output when problem happens. It is like this :
[1;49r [49;1H
[1;50r [49;1H******************************* BUSYBOX SHELL ******************************************
[1;49r [49;1H
[1;50r [49;1Hcan't create nonexistent directory
[1;49r [49;1H
[1;50r [49;1H/ # /system/bin/atxd: not found
[1;49r [49;1H

We can see that "/ #" pattern is present here. ( second last line ) but expect doesn't see it.

Libes book says look for strings that you know most often, so that expect when it matches those strings, will throw away that buffer. Did that also. I have strings like CPU, Memory, Kernel and lots of string patterns. I see full_buffer conditions happen, but I just do exp_contnue

My code is in a procedure and is like this :

set timeout 80
expect {
"CPU" { exp_continue }
"Memory" { exp_continue }
"Kernel" { exp_continue }
"BUSYBOX" { exp_continue }
"offline" { exp_continue }
"online" { exp_continue }

"\/ #" {
puts "System booted successfully (timeout $k_bsecs secs)"
return 0
}
timeout {
puts "System didn't boot exiting (timeout $k_bsecs secs)"
return -1
}
full_buffer {
exp_continue
}
}

[Uwe Klein]

Sar Adde wrote: > I looked at the output when problem happens. It looks like this : [1;1H [79;1H [L [80;64H [10m [7m Offline [79;11H [10m Done > execu [80;64H [10m [7m Online 00:00 [79;23H [10mting testcases." > My actual search pattern is "Done executing" and it is interspread by minicom control characters. > 1. Can you please tell me how to avoid minicom cursor control sequences from appearing, is there > a config on minicom or some stty setting that can avoid it. > 2. In the above case we see "Done execu" string occur, then it got mixed with control characters. > Problem is these control characters can come in after lets say "Don". This means I will not be > able to define a pattern that will match deterministically. Is there a good way to define pattern > in this case. More than it is worth. get rid of the minicom intermediary. use expect directly. i.e. set ttypdev "/dev/tty123" set fd [ open $ttydev RDWR ] # configure the port ( same values as in minicom ) fconfigure $fd -translation binary -encoding binary ;# or anyother config to your liking fconfigure $fd -handshake none -mode 9600,8,n,1 :# or any other config you need ... # spawn from a filehandle ( instead of a process) : spawn -open $fd # continue with your regular expect script.

[Glenn Jackman]

At 2011-08-31 03:46PM, "Sar Adde" wrote:
> Actually timeout is pretty large already. I added timeout so that I can exit from expect.
> I will give the time line :
> Time X seconds : "Done" string is seen on the console.
> Time X seconds : I expect to see "success", but unfortunately I don't.
> Time X+10 seconds : I see "timedout"

[...]

> Timeout is set high, problem is expect is not seeing the "done" pattern.

If you see "Done", then you can't expect to match "done" -- case
sensitivity.

While you're developing an expect script, add this command:
exp_internal 1
to see how expect is matching the patterns you specify.

--
Glenn Jackman
Write a wise saying and your name will live forever. -- Anonymous

[Sar Adde]

Guys,

All your suggestions are very valuable thanks for the help.

Uwe,

I tried accessing serial port directly rather than with minicom. I tried the -mode option and expect didn't like it. Gave error saying -mode option not supported. I am using expect 8.4. So I did stty 9600 < /dev/ttyabc and now I don't see the minicom cursor control characters. But I have not run my script without minicom yet.

Other thing i did is, enabled exp_internal while using minicom, and see some problems.

Problem #1
===========

It is pretty interesting to see that there is order precedence while matching patterns, which could cause a pattern miss that arrives later on if expect_out(buffer) is not processed.
E.g.
Let's say code is like this :
expect {
"xyz" { exp_continue }
"abc" { exp_continue }
"/ #" {
puts " success"
exit
}
timeout {
puts "timed out"
exit
}
}

I am dumping the string I collected in my script. there are lots of control characters because of minicom.:

=============== Start of exp_internal dump =============
expect: does "xxxx_yyyy: nonexistent directory\r\u001b[1;1H\u001b[M\u001b[56;1H\u001b[L/ # /abc_ttt.sh: line 216:" (spawn_id exp17) match glob pattern "xyz"? no
"abc"? yes
expect: set expect_out(0,string) "abc"
expect: set expect_out(spawn_id) "exp17"
expect: set expect_out(buffer) "xxxx_yyyy: nonexistent directory\r\u001b[1;1H\u001b[M\u001b[56;1H\u001b[L/ # /abc"
expect: continuing expect

expect: does "_ttt.sh: line 216:" (spawn_id exp17) match glob pattern "xyz"? no
"abc"? no
"/ #"? no

=============== End of exp_internal dump =============

If you see above, "/ #" arrived before "abc" in the data that expect saw. In the code I have "abc" is before "/ #", so expect saw pattern "abc", cut the original data at "abc", returned the buffer. It took the latest part of string, and started pattern matching again. In my code I am not handling expect_out(buffer) on a match for "abc" and I miss my pattern "/ #".

Is this normal behaviour. Am I supposed to take expect_out(buffer) and search for my success pattern in this case "/ #" again ?

Problem #2
===========

I moved code around to do a "/ #" pattern search first. I see a different problem. I think I would have hit into this problem even if I didn't move my code to search "/ #" first. The pattern I am searching for "/ #" gets clobbers with some bad data.

Dump is as follows :
expect: does "xxxx_yyyy: nonexistent directory\r\u001b[1;1H\u001b[M\u001b[56;1H\u001b[L/\u001b[57;64H\u001b[0m\u001b[10m\u001b[7m Offline \u001b[56;2H\u001b[0m\u001b[10m # " (spawn_id exp17) match glob pattern "/ #"? no
"abc"? no
"xyz"? no

Look at all characters between / and #.

Is there any solution to this problem ? Uwe's suggestion to get rid of minicom is a good one. It will clear up junk characters thrown by minicom. But how should I protect myself if there are some characters dumped by my kernel that might sit between / and #
Any suggestions ?

Please suggest any code changes that can fix above 2 problems.

Thanks for your suggestions guys.

[Uwe Klein]

Sar Adde wrote:
> Guys,
>
> All your suggestions are very valuable thanks for the help.
>
> Uwe,
>
> I tried accessing serial port directly rather than with minicom. I tried the -mode option and
> expect didn't like it. Gave error saying -mode option not supported. I am using expect 8.4. So I
> did stty 9600 < /dev/ttyabc and now I don't see the minicom cursor control characters. But I have
> not run my script without minicom yet.

That is a bit strange.
if you get "mode unknown option" you have opened a regular file
or a nonexistant tty dev ( i.e. a fs node that has no hardware associated )

so just to show what should happen:
uwe@ben:~> expect -v
expect version 5.40.0
uwe@ben:~> expect
expect1.1> set fd [ open /dev/ttyS0 RDWR ]
file4
expect1.2> fconfigure $fd -mode 9600,n,8,1
expect1.3> fconfigure $fd -handshake none
expect1.4> fconfigure $fd -translation binary -encoding binary
# just to see the config:
expect1.5> fconfigure $fd
-blocking 1 -buffering full -buffersize 4096 -encoding binary -eofchar {{} {}} -translation {lf lf}
-mode 9600,n,8,1 -xchar { }
expect1.6> spawn -open $fd
spawn [open ...]
0
expect1.7>

G!
uwe

[Sar Adde]

Uwe,

It works now.

Any suggestions on the other 2 problems I described.

Thanks

[Uwe Klein]

OK we have fixed #1

#2 is expecting the shell prompt at the end of booting, right?

Hmm:
expect -i $spawn_id \
$patt1 {
....
} -ex {/ # } {
puts stderr matched_shellprompt:$expect_out(0,string)
} timeout {
}

I think you will want to expect the space after the prompt too.

if that doesn't work setup the system to have a more verbose $PS1
like adding the system name?

#3 : which one is that ?

uwe

[Sar Adde]

What does the -ex flag do... Can you please explain a little bit more...

Also #3 is "Problem #2" that I mentioned in my previous mail. It is about :

"The pattern I am searching for "/ #" gets clobbers with some bad data"

Thanks

[Uwe Klein]

if it is clobbered
then use the timeout to
kick of sending a
expect ....
} -ex {/ # } {
puts stderr "prompt seen"
return SUCCESS
.. timeout {
# this should prompt the shell to send a prompt
# without danger of it getting mangled
# if the bootup was successfull:
# ( reduce timeout to a reasonable value, do a testrun
# to determine it )
exp_send -i $spawn_id \r
exp_continue
}

> Thanks
-ex ~= exact pattern match, no glob pattern, no regular expression.

maybe read the manpage for expect?
expect is a functionality rich tool!

uwe

[Sar Adde]

Thanks Uwe for your suggestions.

After I got rid of minicom, things seem better.

But I have 1 problem. When I was using minicom, I was using the -C option of minicom to log the output of serial port directly to a file.
After I moved to using fconfigure to configure serial port I am using log_file to capture output of expect to a file.

Problem is on top of getting serial output, I also end up collecting lot of expect output into logfile. Is there a way to just capture the serial port out into file while configuring using fconfigure.

Thanks

[Uwe Klein]

What _extra_ output do you see in the logfile beyond the matched input
_and_ the stuff sent via exp_send ?

( I didn't have any problems in my last project that did about the same )

uwe

[Sar Adde]

log_file <file_name> is capturing information as seen by expect.

It is not capturing exactly what is happening on the uartb.

My expect code runs by giving commands between a device and host at different times. log_file is capturing expect output, and not exactly what is seen on uartb console. Let's say there is command I issue from host, it causes a particular output on host side, which is same as expect output, but a different kind of output actually happens on the console as a result of command on host. I want to capture the output of console, but log_file captures output of host at that point.
What ends up happening is I will have a logfile which has output of hostside as well as device side output.

Is there a way to avoid hostside output, and just capture exactly what is seen on console.

Thanks

[Sar Adde]

Uwe or anyone,

Any suggestions on just capturing serial output when serial port is configured using fconfigure.

Thanks