expect.pm - stdout buffering issue

[Andry]

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.

Now if I put the following command at the end of the script:
$exp->soft_close();
Then the console shows the previously missing output ("ls") at the
very end of the script, but the log file does not include that yet.

It seems there is a general buffering problem with STDOUT.
How can I get things displayed and logged correctly and at the right
time?

Thanks,
Andrea

 

[Josef Moellers]

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.

Now if I put the following command at the end of the script:
$exp->soft_close();
Then the console shows the previously missing output ("ls") at the
very end of the script, but the log file does not include that yet.

It seems there is a general buffering problem with STDOUT.
How can I get things displayed and logged correctly and at the right
time?

More likeley: your expect strings don't match and your script just times
out:

$timeout = 5; vs.
4) sleeping 5 seconds

There are two logging facilities:

1. $exp->exp_internal(1);
IIRC that will tell you what your script expects and what it actually
receives.

2. $exp->log_user(1)
Can't recall what that does ;-)

I usually set these tow if I have problems.

Josef

 

[Josef Moellers]

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"); } ]);

I just notice:

Maybe you want to send a \r rather than a \n?

Josef

 

[Andry]

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"); } ]);

I just notice:

Maybe you want to send a \r rather than a \n?

Josef
--
These are my personal views and not those of Fujitsu Siemens Computers!
Josef Möllers (Pinguinpfleger bei FSC)
        If failure had no penalty success would not be a prize (T..  Pratchett)
Company Details:http://www.fujitsu-siemens.com/imprint.html

Hi Josef,
The script is not timing out anywhere, even if I comment out
$timeout=5, the behavior is the same.
Even replacing \n with \r does not change anything.
I enabled the debug logging with exp_internal, but it doesn't look
very helpful in my case. Here is its output anyway (having the
soft_close command at the very end of the script):
********************************************************************
[root@fedora-c2 perl-scripts]# ./ssh.pl
Spawned 'ssh -l root 10.17.39.29'
spawn id(3)
Pid: 19863
Tty: /dev/pts/4
Expect::spawn('Expect=GLOB(0x9374dbc)','ssh -l root 10.17.39.29')
called at ./ssh.pl line 34
Starting EXPECT pattern matching...
Expect::expect('Expect=GLOB(0x9374dbc)',5,'ARRAY(0x938198c)') 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.

[email protected]'s password:
spawn id(3): Does `[email protected]\'s password: '
match:
pattern #1: -re `[Pp]assword'? YES!!
Before match string: `[email protected]\'s '
Match string: `password'
After match string: `: '
Matchlist: ()
Calling hook CODE(0x9377204)...
Sending 'atis4713\n' to spawn id(3)
Expect:rint('Expect=GLOB(0x9374dbc)','atis4713\x{a}') called at ./
ssh.pl line 37
main::__ANON__('Expect=GLOB(0x9374dbc)') called at /usr/lib/perl5/
site_perl/5.8.3/Expect.pm line 758
Expect::_multi_expect(5,'undef','ARRAY(0x9395304)') called at /usr/
lib/perl5/site_perl/5.8.3/Expect.pm line 563
Expect::expect('Expect=GLOB(0x9374dbc)',5,'ARRAY(0x938198c)') called
at ./ssh.pl line 37
Starting EXPECT pattern matching...
Expect::expect('Expect=GLOB(0x9374dbc)',5,'ARRAY(0x938198c)') called
at ./ssh.pl line 55
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.

Last login: Tue Sep 23 14:20:30 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: Tue Sep 23 14:20:30 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.

[root@svr-mila-testlab2 ~]#
spawn id(3): Does `: \nLast login: Tue Sep 23 14:20:30 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: Tue Sep 23 14:20:30 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@'
Match string: `svr-mila'
After match string: `-testlab2 ~]# '
Matchlist: ()
Calling hook CODE(0x93772c4)...
Sending 'ls -l\n' to spawn id(3)
Expect:rint('Expect=GLOB(0x9374dbc)','ls -l\x{a}') called at ./
ssh.pl line 53
main::__ANON__('Expect=GLOB(0x9374dbc)') called at /usr/lib/perl5/
site_perl/5.8.3/Expect.pm line 758
Expect::_multi_expect(5,'undef','ARRAY(0x93952f8)') called at /usr/
lib/perl5/site_perl/5.8.3/Expect.pm line 563
Expect::expect('Expect=GLOB(0x9374dbc)',5,'ARRAY(0x938198c)') called
at ./ssh.pl line 55
Starting EXPECT pattern matching...
Expect::expect('Expect=GLOB(0x9374dbc)',5,'ARRAY(0x938198c)') called
at ./ssh.pl line 70
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 2360
-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 2290308 Sep 23 14:21 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 2360\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
2290308 Sep 23 14:21 \033[00msb-log.txt\033[00m\r\n-rw-r--r-- 1 root
root 3034 Feb 6 2007 \033[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 2360\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 2290308 Sep 23 14:21 \033[00msb-log.txt\033[00m\r\n-rw-r--r-- 1
root root 3034 Feb 6 2007 \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(0x9377378)...
Sending 'ls\n' to spawn id(3)
Expect:rint('Expect=GLOB(0x9374dbc)','ls\x{a}') called at ./ssh.pl
line 68
main::__ANON__('Expect=GLOB(0x9374dbc)') called at /usr/lib/perl5/
site_perl/5.8.3/Expect.pm line 758
Expect::_multi_expect(5,'undef','ARRAY(0x93819e0)') called at /usr/
lib/perl5/site_perl/5.8.3/Expect.pm line 563
Expect::expect('Expect=GLOB(0x9374dbc)',5,'ARRAY(0x938198c)') called
at ./ssh.pl line 70
Starting EXPECT pattern matching...
Expect::expect('Expect=GLOB(0x9374dbc)',5,'ARRAY(0x9375140)') called
at ./ssh.pl line 88
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[00m \033[00msb-log.txt\033[00m
\033[01;34myum-keys\033[00m\r\n\033[m[root@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\033[m[root@'
Match string: `svr-mila'
After match string: `-testlab2 ~]# '
Matchlist: ()
Calling hook CODE(0x9377444)...
Sending 'exit\n' to spawn id(3)
Expect:rint('Expect=GLOB(0x9374dbc)','exit\x{a}') called at ./
ssh.pl line 88
main::__ANON__('Expect=GLOB(0x9374dbc)') called at /usr/lib/perl5/
site_perl/5.8.3/Expect.pm line 758
Expect::_multi_expect(5,'undef','ARRAY(0x9382408)') called at /usr/
lib/perl5/site_perl/5.8.3/Expect.pm line 563
Expect::expect('Expect=GLOB(0x9374dbc)',5,'ARRAY(0x9375140)') called
at ./ssh.pl line 88
exit
logout
Connection to 10.17.39.29 closed.
[root@fedora-c2 perl-scripts]#
[root@fedora-c2 perl-scripts]#
********************************************************************

As I said in my first post, the operations of the scripts look out of
sync since the sleep commands are executed in the wrong order and the
last "ls" output is not shown until the very end of the script (only
if use soft_close command and the log_file does not caoture that
output anyway).
The commands should be executed in the following order:
ls -l
sleep 2
ls
sleep 5

Instead they are executed like that:
sleep 2
ls -l
sleep 5
ls (only visible if soft_close is present and not captured by log_file
anyway)

Any idea?

 

[Andry]

At 2008-09-23 06:35AM, "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;

In my experience (with expect rather than expect.pm), if you need to
sleep, your match patterns are wrong.  In particular, if you're trying
to match your shell prompt, you should anchor your regex.

I'm not sure to understand what you mean, but the problem is not in my
match pattern ("prompt-string" was just a med up example...).
The expect function matches what I need (as you can see in the debug
generated by exp_internal) but I have a "timing" issue with execution
of sleep commands and also the output of send commands is not sent to
STDOUT when expected (see previous posts).
It looks like expect objects do not send their output to STDOUT
correctly (buffering issue?).

Andrea

 

[Josef Moellers]

output anyway).
The commands should be executed in the following order:
ls -l
sleep 2
ls
sleep 5

Instead they are executed like that:
sleep 2
ls -l
sleep 5
ls (only visible if soft_close is present and not captured by log_file
anyway)

Any idea?

It could very well be a buffering issue.
You could check by adding a "print STDERR "Got password prompt, sending
password\n" to the anonymous sub that's executed when "[Pp]assword" is
matched, and liekwise for the other subs.

Josef
BTW You *do* know, that you had the password in your output?

 

[Josef Moellers]

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

 

[Andry]

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

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):
********************************************************
[email protected]'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:
********************************************************
[email protected]'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

 

[Andry]

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;

Josef

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):
********************************************************
[email protected]'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:
********************************************************
[email protected]'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.

[email protected]'s password:
spawn id(3): Does `[email protected]\'s password: '
match:
pattern #1: -re `[Pp]assword'? YES!!
Before match string: `[email protected]\'s '
Match string: `password'
After match string: `: '
Matchlist: ()
Calling hook CODE(0x9817274)...

Sending...
Sending 'XXXXXXXX\n' to spawn id(3)
Expect:rint('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:rint('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:rint('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:rint('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

 

[Andry]

The paradigm behind Expect is this:  send something and then expect to
see the result.  What you are thinking is that the act of sending
somehow immediately produces outout.  send and expect commands really
occur in pairs.

If I send you an email, I would expect to wait for your reply.
NOT: I send you an email and magically your reply instantly appears.

You should send the ls command, then expect the prompt.  In the output
that contains the prompt you will find the result of ls.

At 2008-09-24 04:25AM, "Andry" 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;

I would write the above as:

    my @match_prompt = ('-re', 'prompt_pattern$');

    $exp->spawn("ssh -l username 10.17.39.29");
    $exp->expect($timeout, @match_prompt);

    $exp->send("password\r");
    $exp->expect($timeout, @match_prompt) or
        die "couldn't see prompt after 'send password'\n";

    $exp->send("ls -l\r");
    $exp->expect($timeout, @match_prompt) or
        die "couldn't see prompt after 'send ls -l'\n";
    # parse $match_patterns for 'ls -l' output

    $exp->send("ls\r");
    $exp->expect($timeout, @match_prompt) or
        die "couldn't see prompt after 'send ls'\n";
    # parse $match_patterns for 'ls' output

    $exp->send("exit\r");
    $exp->expect($timeout, 'eof');

$exp->log_file(undef);
$exp->expect($timeout, [ "prompt-string" => sub { $_[0]->send("exit
\n"); } ]);

Hi Glenn,
Sorry but you did not catch the point.
Doing this:

$exp->expect($timeout, [ "[Pp]assword" => sub { $_[0]->send("password\n"); } ]);

It's exactly the same of doing this:

$exp->expect($timeout, '-re', "[Pp]assword");
$exp->send("password\r");

There is no difference (even '-re' is taken by default in the first
method) execpt that the first method compresses the syntax.
You can try and check it out yourself.

Here the problem is different. STDOUT is not being managed by
Expect.pm as expected.

Now, I found that if I put $exp->log_file(undef) at the very end of
the script (after $exp->soft_close) I can catch the rest of the script
that was being missed out previously. Though the desired result would
be to catch "ls -l" and "ls" but not the rest (exit ssh...). If I put
$exp->log_file(undef) after the last 'send ls' but before $exp-

soft_close() then the output of the last "ls" is missed out.

So, I still see inconsistent behavior with STDOUT for 'sleep' commands
as well as log_file operations.

Any idea?

Thanks,
Andrea

 

[Andry]

 On Sep 24, 1:50 pm, Glenn Jackman <[email protected]> wrote:

 Doing this:

$exp->expect($timeout, [ "[Pp]assword" => sub { $_[0]->send("password\n"); } ]);

 It's exactly the same of doing this:

    $exp->expect($timeout, '-re', "[Pp]assword");
    $exp->send("password\r");

 There is no difference (even '-re' is taken by default in the first
 method) execpt that the first method compresses the syntax.
 You can try and check it out yourself.

I'll take your word, I'm not an Expect.pm user.  I was trying to
belabour the point that the result of a send shows up in the subsequent
expect.

 Here the problem is different. STDOUT is not being managed by
 Expect.pm as expected.

 Now, I found that if I put $exp->log_file(undef) at the very end of
 the script (after $exp->soft_close) I can catch the rest of the script
 that was being missed out previously. Though the desired result would
 be to catch "ls -l" and "ls" but not the rest (exit ssh...). If I put
 $exp->log_file(undef) after the last 'send ls' but before $exp-

Your old code was:

    $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"); }]);

In this case, the "ls" output won't appear until you match the prompt
(in the second expect command).  By that time, you've already turned off
logging.  Another analogy:  you phone me, hang up before I answer, and
wonder why you didn't hear me say "hi".

Turn off logging after you send "exit" and before you expect "eof".

 So, I still see inconsistent behavior with STDOUT for 'sleep' commands
 as well as log_file operations.

I still don't understand why you need to sleep.  The expect command
should block until it either finds a match or times out.  I think your
expectations are wrong concerning when you should see the output from
sent commands.

You said:
GJ> Turn off logging after you send "exit" and before you expect
"eof".

I already tried that and log_file still doesn't capture the last
"ls" (it does it only if I put '$exp->log_file(undef)' after '$exp-

 

[Josef Moellers]

I already tried that and log_file still doesn't capture the last
"ls" (it does it only if I put '$exp->log_file(undef)' after '$exp-

Why should it? As Glenn points out: you fire the "ls" and then forget to
pick up the answer.
Whenever you send a command, you *must* expect() somethign that follows,
otherwise you won't see the response.

Personally I have resorted to this construct:

sub sendexp {
my $exp = shift;
my $cmd = join(' ', @_);
$exp->send("$cmd\r");
$exp->expect($prompt);
# remove echoed command and prompt
# split returned data into lines
return @lines;
}

When starting up, I just have to do a single "$exp->expect(prompt)".
After that, I just have calls to sendexp().

Josef

 

[Andry]

Why should it? As Glenn points out: you fire the "ls" and then forget to
pick up the answer.
Whenever you send a command, you *must* expect() somethign that follows,
otherwise you won't see the response.

Personally I have resorted to this construct:

sub sendexp {
     my $exp = shift;
     my $cmd = join(' ', @_);
     $exp->send("$cmd\r");
     $exp->expect($prompt);
     # remove echoed command and prompt
     # split returned data into lines
     return @lines;

}

When starting up, I just have to do a single "$exp->expect(prompt)".
After that, I just have calls to sendexp().

Josef
--
These are my personal views and not those of Fujitsu Siemens Computers!
Josef Möllers (Pinguinpfleger bei FSC)
        If failure had no penalty success would not be a prize (T..  Pratchett)
Company Details:http://www.fujitsu-siemens.com/imprint.html

Thanks Josef and Glenn,
I thought the last expect statement (the one with the sub doing
send(exit)) would do the job; instead another simple expect statement
needs to put in between and now STDOUT looks complete as well as the
log file.

Nevertheless, the 'sleep' commands still look out of sync. I'm
starting thinking that also some delayed answers from the ssh server
are somehow affecting the script behavior for I/O STDOUT operations
(and I'm curious to try the same thing with telnet instead).
Especially because today I also put some additional logging operations
in the middle of the script (teeing STDOUT). I'm gonna tell you about
that tomorrow and post an updated version of the script.

Thanks,
Andrea

 

[J. Gleixner]

Andry wrote:
[...]

Nevertheless, the 'sleep' commands still look out of sync. I'm
starting thinking that also some delayed answers from the ssh server

No and there's no such thing as an ssh server.

You're script is basically doing:

print "Running ls\n";
#send()
my $out = `ls`;

print "sleeping for 5\n";
sleep 5;

#expect(...)
print "the output of ls: $out\n" if $out;

Expect will run the command, then you tell it what you
expect to happen and/or when that command is finished,
usually by testing if the prompt is being displayed.
At that point your command has finished running and
you can get the output by using before(), or other
methods. Then you can sleep, or send another command
and wait for the prompt. Rinse and repeat...

 

[Andry]

Andry wrote:

[...]

Nevertheless, the 'sleep' commands still look out of sync. I'm
starting thinking that also some delayed answers from the ssh server

No and there's no such thing as an ssh server.

You're script is basically doing:

print "Running ls\n";
#send()
my $out = `ls`;

print "sleeping for 5\n";
sleep 5;

#expect(...)
print "the output of ls: $out\n" if $out;

Expect will run the command, then you tell it what you
expect to happen and/or when that command is finished,
usually by testing if the prompt is being displayed.
At that point your command has finished running and
you can get the output by using before(), or other
methods.  Then you can sleep, or send another command
and wait for the prompt. Rinse and repeat...

Hi guys,
Here is a better explanation of what I mentioned yesterday.
Based on all your previous suggestions and some intuitive attempts, I
found a way to get the script display the STDOUT correctly and log all
the output to the log_file, text-log.txt (playing with expect/sleep
commands). I also added a couple of partial logs ("ls -l" output into
text1-log.txt and "ls" output into text2-log.txt), teeing STDOUT.
Notice that, amazingly, if I remove any of the sleep commands I get
the wrong output collected by text1-log.txt/text2-log.txt.
Here is the script (please, read more after the script text below):
*************************************************************
#!/usr/bin/perl -w
use Expect;
use warnings;
use File::Tee qw(tee);

$Expect::Log_Stdout = 1;
$timeout = 5;
$|=1;

$exp = new Expect();
$exp->raw_pty(1);
$exp->log_user(1);
$exp->log_stdout(1);
$exp->log_file("text-log.txt", "w");

$exp->spawn("ssh -l root 10.17.39.29") or die "Cannot spawn ssh: $!
\n";
$exp->expect($timeout, ['-re', "[Pp]assword" => sub {
$_[0]->send("XXXXXXXXX\n");
sleep 1;
} ]);
$exp->expect($timeout, "prompt-string");
sleep 2;

open(my $oldout, ">&STDOUT")
or die "Can't dup STDOUT; $!";

open my $target1, '>', 'text1-log.txt' or die $!;
tee STDOUT, $target1;

$exp->send("\n");
$exp->expect($timeout, "prompt-string");
$exp->send("\n");
$exp->expect($timeout, ['-ex', "prompt-string" => sub {
$exp->send("ls -l\n");
$exp->expect($timeout, "prompt-string");
sleep 2;
} ] );
$exp->expect($timeout, "prompt-string");
close STDOUT;

open STDOUT, ">&", $oldout
or die "Can't dup \$oldout: $!";

open my $target2, '>', 'text2-log.txt' or die $!;
tee STDOUT, $target2;

$exp->send("\n");
$exp->expect($timeout, "prompt-string");
$exp->send("\n");
$exp->expect($timeout, ['-ex', "prompt-string" => sub {
$exp->send("ls\n");
$exp->expect($timeout, "prompt-string") or die "couldn't see prompt
after 'send ls'\n";
sleep 1;
} ] );

$exp->expect($timeout, "prompt-string");
$exp->send("\n");
close STDOUT;

open STDOUT, ">&", $oldout
or die "Can't dup \$oldout: $!";

$exp->expect($timeout, ['-ex', "prompt-string" => sub {
$exp->send("exit\n");
} ]);

$exp->log_file(undef);
*************************************************************
The problem is that: if you run the same script ten times, only 5 out
of 10 times you get the proper output captured by the proper partial
log file (either text1-log.txt or text2-log.txt).
The rest of the times you get the wrong output logged into text1-
log.txt/text2-log.txt: when this happens, usually text1-log.txt
contains only the few first lines, whereas text2-log.txt contains the
rest of "ls -l" output instead (and not "ls" output!).
The log_file=text-log.txt is always filled with all the expected
output instead.

Since the problem comes out randomly I suspect that the SSH command
response can affect the STDOUT I/O operations. Otherwise I don't see a
reason why the script should give different results when run multiple
times.

Any thought about the above explained issues?

Btw, J.Gleixner, do you think I get some better result using
exp_before() as you mentioned?

Thanks,
Andrea

 

[Andry]

Andry wrote:

[...]

Nevertheless, the 'sleep' commands still look out of sync. I'm
starting thinking that also some delayed answers from the ssh server

No and there's no such thing as an ssh server.

You're script is basically doing:

print "Running ls\n";
#send()
my $out = `ls`;

print "sleeping for 5\n";
sleep 5;

#expect(...)
print "the output of ls: $out\n" if $out;

Expect will run the command, then you tell it what you
expect to happen and/or when that command is finished,
usually by testing if the prompt is being displayed.
At that point your command has finished running and
you can get the output by using before(), or other
methods.  Then you can sleep, or send another command
and wait for the prompt. Rinse and repeat...

Hi guys,
Based on your suggestions and some intuitive attempts, I found a way
to display STDOUT correctly and, at the same time, get all the
expected output logged into log_file=text-log.txt.
I also added a couple of partial log files, teeing STDOUT, putting "ls
-l" output into text1-log.txt and "ls" into text2-log.txt.
Notice that if I remove any of the sleep commands the collected output
of text1-log.txt/text2-log.txt gets messed up.
Here is the script (please read more after the script below):
************************************************************************
#!/usr/bin/perl -w
use Expect;
use warnings;
use File::Tee qw(tee);

$Expect::Log_Stdout = 1;
$timeout = 5;
$|=1;

$exp = new Expect();
$exp->raw_pty(1);
$exp->log_user(1);
$exp->log_stdout(1);
$exp->log_file("text-log.txt", "w");

$exp->spawn("ssh -l root 10.17.39.29") or die "Cannot spawn ssh: $!
\n";
$exp->expect($timeout, ['-re', "[Pp]assword" => sub {
$_[0]->send("XXXXXXXXX\n");
sleep 1;
} ]);
$exp->expect($timeout, "prompt-string");
sleep 2;

open(my $oldout, ">&STDOUT")
or die "Can't dup STDOUT; $!";

open my $target1, '>', 'text1-log.txt' or die $!;
tee STDOUT, $target1;

$exp->send("\n");
$exp->expect($timeout, "prompt-string");
$exp->send("\n");
$exp->expect($timeout, ['-ex', "prompt-string" => sub {
$exp->send("ls -l\n");
$exp->expect($timeout, "prompt-string");
sleep 2;
} ] );
$exp->expect($timeout, "prompt-string");
close STDOUT;

open STDOUT, ">&", $oldout
or die "Can't dup \$oldout: $!";

open my $target2, '>', 'text2-log.txt' or die $!;
tee STDOUT, $target2;

$exp->send("\n");
$exp->expect($timeout, "prompt-string");
$exp->send("\n");
$exp->expect($timeout, ['-ex', "prompt-string" => sub {
$exp->send("ls\n");
$exp->expect($timeout, "prompt-string") or die "couldn't see prompt
after 'send ls'\n";
sleep 1;
} ] );

$exp->expect($timeout, "prompt-string");
$exp->send("\n");
close STDOUT;

open STDOUT, ">&", $oldout
or die "Can't dup \$oldout: $!";

$exp->expect($timeout, ['-ex', "prompt-string" => sub {
$exp->send("exit\n");
} ]);

$exp->log_file(undef);
************************************************************************
But the problem is that if I run the same script ten times, 5 out of
10 times the wrong output is captured by text1-log.txt/text2-log.txt.
That is, text1-log.txt only collects the first few lines of output
while text2-log.txt collects the rest of "ls -l" output (and not "ls"
output).
Since the problem occurs in a random way, I suspect that a kind of
jitter in SSH responses can affect STDOUT I/O operations of the
script. Otherwise I don't see a reason why the script should give
different results when run multiple times.

Any thought about the above explained issues?

Btw, J.Gleixner, do you think I can get some better result using the
exp_before() you mentioned?

Thanks,
Andrea

 

[Josef Moellers]

Andry wrote:

[...]

Nevertheless, the 'sleep' commands still look out of sync. I'm
starting thinking that also some delayed answers from the ssh server

No and there's no such thing as an ssh server.

You're script is basically doing:

print "Running ls\n";
#send()
my $out = `ls`;

print "sleeping for 5\n";
sleep 5;

#expect(...)
print "the output of ls: $out\n" if $out;

Expect will run the command, then you tell it what you
expect to happen and/or when that command is finished,
usually by testing if the prompt is being displayed.
At that point your command has finished running and
you can get the output by using before(), or other
methods. Then you can sleep, or send another command
and wait for the prompt. Rinse and repeat...

Hi guys,
Here is a better explanation of what I mentioned yesterday.
Based on all your previous suggestions and some intuitive attempts, I
found a way to get the script display the STDOUT correctly and log all
the output to the log_file, text-log.txt (playing with expect/sleep
commands). I also added a couple of partial logs ("ls -l" output into
text1-log.txt and "ls" output into text2-log.txt), teeing STDOUT.
Notice that, amazingly, if I remove any of the sleep commands I get
the wrong output collected by text1-log.txt/text2-log.txt.
Here is the script (please, read more after the script text below):
*************************************************************

[ code removed ]

*************************************************************
The problem is that: if you run the same script ten times, only 5 out
of 10 times you get the proper output captured by the proper partial
log file (either text1-log.txt or text2-log.txt).
The rest of the times you get the wrong output logged into text1-
log.txt/text2-log.txt: when this happens, usually text1-log.txt
contains only the few first lines, whereas text2-log.txt contains the
rest of "ls -l" output instead (and not "ls" output!).
The log_file=text-log.txt is always filled with all the expected
output instead.

Since the problem comes out randomly I suspect that the SSH command
response can affect the STDOUT I/O operations. Otherwise I don't see a
reason why the script should give different results when run multiple
times.

Any thought about the above explained issues?

Btw, J.Gleixner, do you think I get some better result using
exp_before() as you mentioned?

I tried this and I don't see any differences in the files other than
modification times and/or sizes of files affected by the logins.

Very strange,

Josef

 

[Andry]

Andry wrote:
[...]
Nevertheless, the 'sleep' commands still look out of sync. I'm
starting thinking that also some delayed answers from the ssh server
No and there's no such thing as an ssh server.
You're script is basically doing:
print "Running ls\n";
#send()
my $out = `ls`;
print "sleeping for 5\n";
sleep 5;
#expect(...)
print "the output of ls: $out\n" if $out;
Expect will run the command, then you tell it what you
expect to happen and/or when that command is finished,
usually by testing if the prompt is being displayed.
At that point your command has finished running and
you can get the output by using before(), or other
methods.  Then you can sleep, or send another command
and wait for the prompt. Rinse and repeat...

Hi guys,
Here is a better explanation of what I mentioned yesterday.
Based on all your previous suggestions and some intuitive attempts, I
found a way to get the script display the STDOUT correctly and log all
the output to the log_file, text-log.txt (playing with expect/sleep
commands). I also added a couple of partial logs ("ls -l" output into
text1-log.txt and "ls" output into text2-log.txt), teeing STDOUT.
Notice that, amazingly, if I remove any of the sleep commands I get
the wrong output collected by text1-log.txt/text2-log.txt.
Here is the script (please, read more after the script text below):
*************************************************************

[ code removed ]

*************************************************************
The problem is that: if you run the same script ten times, only 5 out
of 10 times you get the proper output captured by the proper partial
log file (either text1-log.txt or text2-log.txt).
The rest of the times you get the wrong output logged into text1-
log.txt/text2-log.txt: when this happens, usually text1-log.txt
contains only the few first lines, whereas text2-log.txt contains the
rest of "ls -l" output instead (and not "ls" output!).
The log_file=text-log.txt is always filled with all the expected
output instead.

Since the problem comes out randomly I suspect that the SSH command
response can affect the STDOUT I/O operations. Otherwise I don't see a
reason why the script should give different results when run multiple
times.

Any thought about the above explained issues?

Btw, J.Gleixner, do you think I get some better result using
exp_before() as you mentioned?

I tried this and I don't see any differences in the files other than
modification times and/or sizes of files affected by the logins.

Very strange,

Josef
--
These are my personal views and not those of Fujitsu Siemens Computers!
Josef Möllers (Pinguinpfleger bei FSC)
        If failure had no penalty success would not be a prize (T..  Pratchett)
Company Details:http://www.fujitsu-siemens.com/imprint.html

Hi all,
After changing the SSH server station, the problem of random
inaccuracy of collected lines from STDOUT has gone away.
So, it seems that Expect for Perl is really sensitive to possible
"jitter" of response messages from a remote terminal (SSH/Telnet
server).
Besides, when building the final script with several repeated
operations like the ones described in this discussion, I had to tune/
tick the correct collection of lines (to guarantee proper output at
the right time) putting multiple expect/send couples (doing dummy
actions, like a newline character...) before each "close STDOUT"
command in order to flush STDOUT as expected. The correct sequence of
such operations was achieved with an empirical method (trying and
trying...).
So, in my opinion, as far as I could experience, Expect for Perl does
not perform very well at all...
Generally speaking, I'd rather use the usual TCL/Expect.

Thanks to all for your support during this discussion,
Andrea