Re: expect.pm - stdout buffering issue
- From: Andry <yandry77@xxxxxxxxx>
- Date: Wed, 24 Sep 2008 02:30:28 -0700 (PDT)
On 24 Set, 10:25, Andry <yandr...@xxxxxxxxx> wrote:
On 23 Set, 18:01, Josef Moellers <5502109103600...@xxxxxxxxxxx> wrote:
Andry wrote:
Hi all,
I have the following script:
******************************************************************
#!/usr/bin/perl -w
use Expect;
$timeout = 5;
$|=1;
$exp = new Expect();
$exp->raw_pty(1);
$exp->log_file("output.log", "w");
$exp->spawn("ssh -l username 10.17.39.29");
$exp->expect($timeout, [ "[Pp]assword" => sub { $_[0]->send("password
\n"); } ]);
$exp->expect($timeout, [ "prompt-string" => sub { $_[0]->send("ls -l
\n"); } ]);
sleep 2;
$exp->expect($timeout, [ "prompt-string" => sub { $_[0]->send("ls
\n"); } ]);
sleep 5;
$exp->log_file(undef);
$exp->expect($timeout, [ "prompt-string" => sub { $_[0]->send("exit
\n"); } ]);
******************************************************************
When I run the script, the console (stdout) shows:
1) ssh (login...)...
2) sleeping 2 seconds
3) "ls -l" output
4) sleeping 5 seconds
... the script quits without displaying the output of the second
command "ls"
Even the log file does not contain the missing output.
On my way home, I have been thinking about this (with this miserable
weather one *has* to think about something else) ...
In a wider sense, it has nothing to do with buffering.
What happens is:
You (disguised as a Perl/Expect script) wait for the password prompt and
send the password. Then you wait for the shell prompt and send the ls
command. Then you sleep for 2 seconds. In the meantime, the remote "ls
-l" produces output, but there is no-one there to notice.
Then you wait for the next shell prompt. *Now* you have to sift through
ls' output to look for the prompt (btw. here Glenn's remark about
anchoring comes into play, if one of the file names would contain the
prompt as a substring!). While sifting though the output, it will be
echoed to the console.
When you find the prompt, you send the next "ls" command and the
previous section hits you again.
So, it's not classical buffering but rather a postponed reading/echoing
of output produced earlier (of course, pedantics would call this
buffering, too, ...)
What you are expecting is the equivalent of
expect(prompt)
send("ls -l\r")
expect(prompt) << Here you get "ls -l"'s output
sleep 2
send("ls\r")
expect(prompt) << Here you get "ls"'s output
sleep 5;
HTH,
Josef
--
Mails please to josef dot moellers
and I'm on gmx dot de.
Hi Josef,
I checked and the prompt string is not present in any line of the "ls"
output.
Actually the problem starts even before that: right after sending the
password, the output shows that the script executes the first sleep (2
seconds) even BEFORE sending the first "ls -l".
So the problem is not related to unexpected (or not timely) matching
of the prompt string.
I put a couple of "print" before and after each "send" command to
better understand the timing issue.
'print "\nSending...\n"' is put right before each 'send'.
'print "\n...Sent!\n"' is put right after each 'send' (before the
'sleep').
Here is the output I get (I typed comments to highlight when the
'sleep' occurs):
********************************************************
r...@xxxxxxxxxxx's password:
Sending...
...Sent!
Last login: Wed Sep 24 09:57:48 2008 from 10.17.91.83
Welcome to the Milan TestLab server
If you're not part of the TestLab team, you're not welcome anymore...
Sending...
...Sent!
########## NOW IS SLEEPING TWO SECONDS ##########
[root@svr-mila-testlab2 ~]# ls -l
total 2364
-rw-r--r-- 1 root root 33980 Feb 8 2007 1
-rw------- 1 root root 1534 Feb 5 2007 anaconda-ks.cfg
drwxr-xr-x 2 root root 4096 Feb 5 2007 Desktop
-rw-r--r-- 1 root root 38253 Feb 5 2007 install.log
-rw-r--r-- 1 root root 4475 Feb 5 2007 install.log.syslog
-rw-r--r-- 1 root root 2297093 Sep 24 10:01 sb-log.txt
-rw-r--r-- 1 root root 3034 Feb 6 2007 xorg.conf.new
drwxr-xr-x 2 root root 4096 Feb 7 2007 yum-keys
[root@svr-mila-testlab2 ~]#
Sending...
...Sent!
########## NOW IS SLEEPING FIVE SECONDS ##########
ls
1 Desktop install.log.syslog xorg.conf.new
anaconda-ks.cfg install.log sb-log.txt yum-keys
[root@svr-mila-testlab2 ~]#
Sending...
...Sent!
exit
logout
Connection to 10.17.39.29 closed.
********************************************************
Instead, what I expect should be something like this:
********************************************************
r...@xxxxxxxxxxx's password:
Sending...
Last login: Wed Sep 24 09:57:48 2008 from 10.17.91.83
Welcome to the Milan TestLab server
If you're not part of the TestLab team, you're not welcome anymore...
[root@svr-mila-testlab2 ~]#
...Sent!
Sending...
ls -l
total 2364
-rw-r--r-- 1 root root 33980 Feb 8 2007 1
-rw------- 1 root root 1534 Feb 5 2007 anaconda-ks.cfg
drwxr-xr-x 2 root root 4096 Feb 5 2007 Desktop
-rw-r--r-- 1 root root 38253 Feb 5 2007 install.log
-rw-r--r-- 1 root root 4475 Feb 5 2007 install.log.syslog
-rw-r--r-- 1 root root 2297093 Sep 24 10:01 sb-log.txt
-rw-r--r-- 1 root root 3034 Feb 6 2007 xorg.conf.new
drwxr-xr-x 2 root root 4096 Feb 7 2007 yum-keys
[root@svr-mila-testlab2 ~]#
...Sent!
########## NOW IS SLEEPING TWO SECONDS ##########
Sending...
ls
1 Desktop install.log.syslog xorg.conf.new
anaconda-ks.cfg install.log sb-log.txt yum-keys
[root@svr-mila-testlab2 ~]#
...Sent!
########## NOW IS SLEEPING FIVE SECONDS ##########
Sending...
exit
...Sent!
logout
Connection to 10.17.39.29 closed.
********************************************************
Maybe it's ok that "...Sent!" is displayed right after "Sending..."
because the output of the 'send' command takes longer to display and
it comes after, but the time of displaying "Sending..." is wrong
anyway and, above all, the time of 'sleep' is wrong.
Of course this is trivial example but I need to display output lines
and execute 'sleep' commands in the proper order to build a more
complex non-interactive script.
Any idea?
Thanks,
Andrea
I ran again the exp_internal tool for debug and found that somehow the
'sleep' commands are correctly executed but the output is displayed at
the wrong time, see below (I added comments to highlight 'sleep'
executions that are not logged by exp_internal):
**************************************************************
Spawned 'ssh -l root 10.17.39.29'
spawn id(3)
Pid: 31550
Tty: /dev/pts/4
Expect::spawn('Expect=GLOB(0x9817238)','ssh -l root 10.17.39.29')
called
at ./ssh.pl line 34
Starting EXPECT pattern matching...
Expect::expect('Expect=GLOB(0x9817238)',5,'ARRAY(0x9822520)') called
at
../ssh.pl line 37
spawn id(3): list of patterns:
#1: -re `[Pp]assword'
spawn id(3): Does `'
match:
pattern #1: -re `[Pp]assword'? No.
root@xxxxxxxxxxx's password:
spawn id(3): Does `root@xxxxxxxxxxx\'s password: '
match:
pattern #1: -re `[Pp]assword'? YES!!
Before match string: `root@xxxxxxxxxxx\'s '
Match string: `password'
After match string: `: '
Matchlist: ()
Calling hook CODE(0x9817274)...
Sending...
Sending 'XXXXXXXX\n' to spawn id(3)
Expect::print('Expect=GLOB(0x9817238)','XXXXXXXX\x{a}') called at ./
ssh.
pl line 37
main::__ANON__('Expect=GLOB(0x9817238)') called at /usr/lib/perl5/
site_p
erl/5.8.3/Expect.pm line 758
Expect::_multi_expect(5,'undef','ARRAY(0x98380d4)') called at /usr/
lib/p
erl5/site_perl/5.8.3/Expect.pm line 563
Expect::expect('Expect=GLOB(0x9817238)',5,'ARRAY(0x9822520)') called
at
../ssh.pl line 37
....Sent!
Starting EXPECT pattern matching...
Expect::expect('Expect=GLOB(0x9817238)',5,'ARRAY(0x98069ec)') called
at
../ssh.pl line 56
spawn id(3): list of patterns:
#1: -re `svr-mila'
spawn id(3): Does `: '
match:
pattern #1: -re `svr-mila'? No.
spawn id(3): Does `: \n'
match:
pattern #1: -re `svr-mila'? No.
spawn id(3): Does `: \nLast login: Wed Sep 24 11:05:15 2008 from
10.17.91.83\r\r
\nWelcome to the Milan TestLab server\r\nIf you\'re not part of the
TestLab team
, you\'re not welcome anymore...\r\n\r\n'
match:
pattern #1: -re `svr-mila'? No.
Last login: Wed Sep 24 11:05:15 2008 from 10.17.91.83
Welcome to the Milan TestLab server
If you're not part of the TestLab team, you're not welcome anymore...
spawn id(3): Does `: \nLast login: Wed Sep 24 11:05:15 2008 from
10.17.91.83\r\r
\nWelcome to the Milan TestLab server\r\nIf you\'re not part of the
TestLab team
, you\'re not welcome anymore...\r\n\r\n[root@svr-mila-testlab2 ~]# '
match:
pattern #1: -re `svr-mila'? YES!!
Before match string: `: \nLast login: Wed Sep 24 11:05:15 2008
from 10.17.91
..83\r\r\nWelcome to the Milan TestLab server\r\nIf you\'re not part of
the TestL
ab team, you\'re not welcome anymore...\r\n\r\n[root@'
Match string: `svr-mila'
After match string: `-testlab2 ~]# '
Matchlist: ()
Calling hook CODE(0x981743c)...
Sending 'ls -l\n' to spawn id(3)
Expect::print('Expect=GLOB(0x9817238)','ls -l\x{a}') called at ./
ssh.pl
line 53
main::__ANON__('Expect=GLOB(0x9817238)') called at /usr/lib/perl5/
site_p
erl/5.8.3/Expect.pm line 758
Expect::_multi_expect(5,'undef','ARRAY(0x97a9bf4)') called at /usr/
lib/p
erl5/site_perl/5.8.3/Expect.pm line 563
Expect::expect('Expect=GLOB(0x9817238)',5,'ARRAY(0x98069ec)') called
at
../ssh.pl line 56
[root@svr-mila-testlab2 ~]#
Sending...
....Sent!
########## NOW IT'S SLEEPING 2 SECONDS ##########
Starting EXPECT pattern matching...
Expect::expect('Expect=GLOB(0x9817238)',5,'ARRAY(0x98382a8)') called
at
../ssh.pl line 72
spawn id(3): list of patterns:
#1: -re `svr-mila'
spawn id(3): Does `-testlab2 ~]# '
match:
pattern #1: -re `svr-mila'? No.
ls -l
total 2368
-rw-r--r-- 1 root root 33980 Feb 8 2007 1
-rw------- 1 root root 1534 Feb 5 2007 anaconda-ks.cfg
drwxr-xr-x 2 root root 4096 Feb 5 2007 Desktop
-rw-r--r-- 1 root root 38253 Feb 5 2007 install.log
-rw-r--r-- 1 root root 4475 Feb 5 2007 install.log.syslog
-rw-r--r-- 1 root root 2299385 Sep 24 11:06 sb-log.txt
-rw-r--r-- 1 root root 3034 Feb 6 2007 xorg.conf.new
drwxr-xr-x 2 root root 4096 Feb 7 2007 yum-keys
[root@svr-mila-testlab2 ~]#
spawn id(3): Does `-testlab2 ~]# ls -l\r\n\033[00mtotal 2368\r\n-rw-r--
r-- 1 roo
t root 33980 Feb 8 2007 \033[00m1\033[00m\r\n-rw------- 1 root
root 1534
Feb 5 2007 \033[00manaconda-ks.cfg\033[00m\r\ndrwxr-xr-x 2 root
root 4096 F
eb 5 2007 \033[01;34mDesktop\033[00m\r\n-rw-r--r-- 1 root root
38253 Feb 5
2007 \033[00minstall.log\033[00m\r\n-rw-r--r-- 1 root root 4475
Feb 5 2007
\033[00minstall.log.syslog\033[00m\r\n-rw-r--r-- 1 root root 2299385
Sep 24 11:
06 \033[00msb-log.txt\033[00m\r\n-rw-r--r-- 1 root root 3034 Feb
6 2007 \03
3[00mxorg.conf.new\033[00m\r\ndrwxr-xr-x 2 root root 4096 Feb 7
2007 \033[0
1;34myum-keys\033[00m\r\n\033[m[root@svr-mila-testlab2 ~]# '
match:
pattern #1: -re `svr-mila'? YES!!
Before match string: `-testlab2 ~]# ls -l\r\n\033[00mtotal 2368\r
\n-rw-r--r-
- 1 root root 33980 Feb 8 2007 \033[00m1\033[00m\r\n-rw------- 1
root root
1534 Feb 5 2007 \033[00manaconda-ks.cfg\033[00m\r\ndrwxr-xr-x 2
root root
4096 Feb 5 2007 \033[01;34mDesktop\033[00m\r\n-rw-r--r-- 1 root
root 38253
Feb 5 2007 \033[00minstall.log\033[00m\r\n-rw-r--r-- 1 root root
4475 Feb
5 2007 \033[00minstall.log.syslog\033[00m\r\n-rw-r--r-- 1 root root
2299385 Sep
24 11:06 \033[00msb-log.txt\033[00m\r\n-rw-r--r-- 1 root root 3034
Feb 6 2
007 \033[00mxorg.conf.new\033[00m\r\ndrwxr-xr-x 2 root root 4096
Feb 7 2007
\033[01;34myum-keys\033[00m\r\n\033[m[root@'
Match string: `svr-mila'
After match string: `-testlab2 ~]# '
Matchlist: ()
Calling hook CODE(0x9814f54)...
Sending...
Sending 'ls\n' to spawn id(3)
Expect::print('Expect=GLOB(0x9817238)','ls\x{a}') called at ./ssh.pl
lin
e 69
main::__ANON__('Expect=GLOB(0x9817238)') called at /usr/lib/perl5/
site_p
erl/5.8.3/Expect.pm line 758
Expect::_multi_expect(5,'undef','ARRAY(0x98380e0)') called at /usr/
lib/p
erl5/site_perl/5.8.3/Expect.pm line 563
Expect::expect('Expect=GLOB(0x9817238)',5,'ARRAY(0x98382a8)') called
at
../ssh.pl line 72
....Sent!
########## NOW IT'S SLEEPING FIVE SECONDS ###########
Starting EXPECT pattern matching...
Expect::expect('Expect=GLOB(0x9817238)',5,'ARRAY(0x9575530)') called
at
../ssh.pl line 90
spawn id(3): list of patterns:
#1: -re `svr-mila'
spawn id(3): Does `-testlab2 ~]# '
match:
pattern #1: -re `svr-mila'? No.
ls
1 Desktop install.log.syslog xorg.conf.new
anaconda-ks.cfg install.log sb-log.txt yum-keys
[root@svr-mila-testlab2 ~]#
spawn id(3): Does `-testlab2 ~]# ls\r\n\033[00m
\033[00m1\033[00m
\033[01;34mDesktop\033[00m \033[00minstall.log.syslog\033[00m
\033[00mxorg
..conf.new\033[00m\r\n\033[00manaconda-ks.cfg\033[00m
\033[00minstall.log\033[00
m \033[00msb-log.txt\033[00m \033[01;34myum-keys\033[00m\r\n
\033[m[roo
t@svr-mila-testlab2 ~]# '
match:
pattern #1: -re `svr-mila'? YES!!
Before match string: `-testlab2 ~]# ls\r\n\033[00m
\033[00m1\033[00m
\033[01;34mDesktop\033[00m \033[00minstall.log.syslog
\033[00m \033[
00mxorg.conf.new\033[00m\r\n\033[00manaconda-ks.cfg\033[00m
\033[00minstall.log
\033[00m \033[00msb-log.txt\033[00m \033[01;34myum-keys
\033[00m\r\n\03
3[m[root@'
Match string: `svr-mila'
After match string: `-testlab2 ~]# '
Matchlist: ()
Calling hook CODE(0x98150f8)...
Sending...
Sending 'exit\n' to spawn id(3)
Expect::print('Expect=GLOB(0x9817238)','exit\x{a}') called at ./
ssh.pl l
ine 90
main::__ANON__('Expect=GLOB(0x9817238)') called at /usr/lib/perl5/
site_p
erl/5.8.3/Expect.pm line 758
Expect::_multi_expect(5,'undef','ARRAY(0x9838074)') called at /usr/
lib/p
erl5/site_perl/5.8.3/Expect.pm line 563
Expect::expect('Expect=GLOB(0x9817238)',5,'ARRAY(0x9575530)') called
at
../ssh.pl line 90
....Sent!
exit
logout
Connection to 10.17.39.29 closed.
**********************************************************
Eventhough I could ignore the display to console, I still have the
problem that the log_file does not capture the last part of the script
(from the second "ls" on). So, I still think there is a real issue
with STDOUT buffering.
Any way out?
Thanks,
Andrea
.
- References:
- expect.pm - stdout buffering issue
- From: Andry
- Re: expect.pm - stdout buffering issue
- From: Andry
- expect.pm - stdout buffering issue
- Prev by Date: Re: expect.pm - stdout buffering issue
- Next by Date: Re: expect.pm - stdout buffering issue
- Previous by thread: Re: expect.pm - stdout buffering issue
- Next by thread: Re: expect.pm - stdout buffering issue
- Index(es):
Relevant Pages
|
