expectperl-discuss

[Expectperl-discuss] Expect issues with custom OpenBSD and application interaction.

[Eric T. <zi...@gm...>]

Hey,

I am debugging a script using perl expect to ssh into a OpenBSD server that
is running a custom OS on top of the BSD kernel.  The OS resembles that of a
Cisco IOS (menu driven type thing).  The problem I am having is that the
perl script spawns the ssh connection and logs in successfully.  It then
matches on the first prompt '/# /' and sends a command to the remote
server.  The command gets sent and the command gets echoed back and then the
connection gets killed without waiting the timeout or anything.  I am
assuming it is a pty ot tty issue due to the nature of the remote system but
have debugged these avenues with no results.

I am unsure of how to proceed with this.  The funny thing is that this perl
expect script reads properly from the socket until after the first command
is sent to the OS running on top of the OpenBSD kernel.  It does expect
match correclty on the first custom OS prompt though so I would assume that
it is interacting with this OS properly.

Here is some debugging output of this session:

____________________________________________________________________________________________
$Expect::Exp_Internal = 1; Output:
Spawned 'ssh -l admin batista'
        spawn id(5)
        Pid: 16540
        Tty: /dev/pts/5
 at /usr/lib/perl5/site_perl/5.8.6/Expect.pm line 179
        Expect::spawn('Expect', 'ssh -l admin batista') called at bug_15725
line 24
Starting EXPECT pattern matching...
 at /usr/lib/perl5/site_perl/5.8.6/Expect.pm line 548
        Expect::expect('Expect=GLOB(0x9cd4384)', 30, 'passphrase') called at
bug_15725 line 30
spawn id(5): list of patterns:
  #1: -ex `'


spawn id(5): Does `'
match:
  pattern #1: -ex `'? No.

Waiting for new data (30 seconds)...
Enter passphrase for key '/root/.ssh/id_dsa':
spawn id(5): Does `'
match:
  pattern #1: -ex `'? YES!!
    Before match string: `'
    Match string: `'
    After match string: `'
    Matchlist: ()
Returning from expect successfully.
...recieved password prompt
Sending '' to spawn id(5)
 at /usr/lib/perl5/site_perl/5.8.6/Expect.pm line 1236
        Expect::print('Expect=GLOB(0x9cd4384)', 'somepass\x{a}') called at
bug_15725 line 36
Starting EXPECT pattern matching...
 at /usr/lib/perl5/site_perl/5.8.6/Expect.pm line 548
        Expect::expect('Expect=GLOB(0x9cd4384)', 30, '/# ') called at
bug_15725 line 38
spawn id(5): list of patterns:
  #1: -ex `'


spawn id(5): Does `'
match:
  pattern #1: -ex `'? No.

Waiting for new data (30 seconds)...


spawn id(5): Does `'
match:
  pattern #1: -ex `'? No.

Waiting for new data (30 seconds)...
Last login: CLI on Tue Jul 25 02:50:45 2006 from 10.0.2.229

spawn id(5): Does `'
match:
  pattern #1: -ex `'? No.

Waiting for new data (30 seconds)...

Welcome to Custom OS


spawn id(5): Does `'
match:
  pattern #1: -ex `'? No.

Waiting for new data (30 seconds)...
admin@batista:/#
spawn id(5): Does `'
match:
  pattern #1: -ex `'? YES!!
    Before match string: `'
    Match string: `'
    After match string: `'
    Matchlist: ()
Returning from expect successfully.
Sending '' to spawn id(5)
 at /usr/lib/perl5/site_perl/5.8.6/Expect.pm line 1236
        Expect::print('Expect=GLOB(0x9cd4384)', 'sys show\x{a}') called at
bug_15725 line 47
Starting EXPECT pattern matching...
 at /usr/lib/perl5/site_perl/5.8.6/Expect.pm line 548
        Expect::expect('Expect=GLOB(0x9cd4384)', 30, '/# ') called at
bug_15725 line 49
spawn id(5): list of patterns:
  #1: -ex `'


spawn id(5): Does `'
match:
  pattern #1: -ex `'? No.

Waiting for new data (30 seconds)...
sys show

spawn id(5): Does `'
match:
  pattern #1: -ex `'? No.

Waiting for new data (30 seconds)...
Connection to batista closed.

spawn id(5): Does `'
match:
  pattern #1: -ex `'? No.

Waiting for new data (30 seconds)...
Returning from expect with TIMEOUT or EOF
Error 03::Never got sec prompt, 3:Child PID 16540 exited with status 0
____________________________________________________________________________________________

Here is some,  $Expect::Debug = 3; Output:

____________________________________________________________________________________________
Spawned 'ssh -l admin batista'
        spawn id(5)
        Pid: 16567
        Tty: /dev/pts/5
 at /usr/lib/perl5/site_perl/5.8.6/Expect.pm line 179
        Expect::spawn('Expect', 'ssh -l admin batista') called at bug_15725
line 24
Use of uninitialized value in concatenation (.) or string at
/usr/lib/perl5/site_perl/5.8.6/Expect.pm line 1402.
Closing .
 at /usr/lib/perl5/site_perl/5.8.6/Expect.pm line 1402
        Expect::hard_close('Expect=GLOB(0x9436ca0)') called at
/usr/lib/perl5/site_perl/5.8.6/Expect.pm line 1592
        Expect::DESTROY('Expect=GLOB(0x9436ca0)') called at bug_15725 line
28
        eval {...} called at bug_15725 line 28
Use of uninitialized value in concatenation (.) or string at
/usr/lib/perl5/site_perl/5.8.6/Expect.pm line 1405.
 closed.
Starting EXPECT pattern matching...
 at /usr/lib/perl5/site_perl/5.8.6/Expect.pm line 548
        Expect::expect('Expect=GLOB(0x96403bc)', 30, 'passphrase') called at
bug_15725 line 30
spawn id(5): beginning expect.
        Timeout: 30 seconds.
        Current time: Mon Jul 24 22:54:00 2006
Waiting for new data (30 seconds)...
spawn id(5): new data.
spawn id(5): read 46 byte(s).
Enter passphrase for key '/root/.ssh/id_dsa': Returning from expect
successfully.
  spawn id(5): accumulator: `'
...recieved password prompt
Starting EXPECT pattern matching...
 at /usr/lib/perl5/site_perl/5.8.6/Expect.pm line 548
        Expect::expect('Expect=GLOB(0x96403bc)', 30, '/# ') called at
bug_15725 line 38
spawn id(5): beginning expect.
        Timeout: 30 seconds.
        Current time: Mon Jul 24 22:54:00 2006
Waiting for new data (30 seconds)...
spawn id(5): new data.
spawn id(5): read 2 byte(s).

Waiting for new data (30 seconds)...
spawn id(5): new data.
spawn id(5): read 61 byte(s).
Last login: CLI on Tue Jul 25 02:51:47 2006 from 10.0.1.125
Waiting for new data (30 seconds)...
spawn id(5): new data.
spawn id(5): read 113 byte(s).

Welcome to CustomOS

Waiting for new data (30 seconds)...
spawn id(5): new data.
spawn id(5): read 17 byte(s).
admin@batista:/# Returning from expect successfully.
  spawn id(5): accumulator: `'
Starting EXPECT pattern matching...
 at /usr/lib/perl5/site_perl/5.8.6/Expect.pm line 548
        Expect::expect('Expect=GLOB(0x96403bc)', 30, '/# ') called at
bug_15725 line 49
spawn id(5): beginning expect.
        Timeout: 30 seconds.
        Current time: Mon Jul 24 22:54:01 2006
Waiting for new data (30 seconds)...
spawn id(5): new data.
spawn id(5): read 10 byte(s).
sys show
Waiting for new data (30 seconds)...
spawn id(5): new data.
spawn id(5): read 32 byte(s).
Connection to batista closed.
Waiting for new data (30 seconds)...
spawn id(5): new data.
spawn id(5): EOF
spawn id(5): exit(0x00)
spawn id(5): closing...
Closing spawn id(5).
 at /usr/lib/perl5/site_perl/5.8.6/Expect.pm line 1402
        Expect::hard_close('Expect=GLOB(0x96403bc)') called at
/usr/lib/perl5/site_perl/5.8.6/Expect.pm line 867
        Expect::_multi_expect(30, 'undef', 'ARRAY(0x969b074)') called at
/usr/lib/perl5/site_perl/5.8.6/Expect.pm line 552
        Expect::expect('Expect=GLOB(0x96403bc)', 30, '/# ') called at
bug_15725 line 49
spawn id(5) closed.
Returning from expect with TIMEOUT or EOF
Error 03::Never got sec prompt, 3:Child PID 16567 exited with status 0
Closing spawn id(5).
 at /usr/lib/perl5/site_perl/5.8.6/Expect.pm line 1402
        Expect::hard_close('Expect=GLOB(0x96403bc)') called at
/usr/lib/perl5/site_perl/5.8.6/Expect.pm line 1592
        Expect::DESTROY('Expect=GLOB(0x96403bc)') called at bug_15725 line 0
        eval {...} called at bug_15725 line 0

____________________________________________________________________________________________

Re: [Expectperl-discuss] Expect issues with custom OpenBSD and application interaction.

[Roland G. <RGi...@cp...>]

Hi Eric,

please upgrade to the latest Expect version (1.20), as you obviously
have a version where _make_readable() doesn't work. :-( I'm sure that
the debug output will make much more sense then... ;-)

Ah, yes, and sorry to all for that mistake! That blunder was a good case
to show that you always should follow the procedure: first create a
testcase for the bug, showing the bug in the old version. Then fix it
and test it with the testcase...

Cheers! Roland

> spawn id(5): Does `'
> match:
>   pattern #1: -ex `'? YES!!
>     Before match string: `'
>     Match string: `'
>     After match string: `'
>     Matchlist: ()

--
RGi...@cp...

Re: [Expectperl-discuss] Expect issues with custom OpenBSD and application interaction.

[Eric T. <zi...@gm...>]

Roland,

Thanks for the heads up on the version.  I did upgrade and it did make a
little more sense but I still have the same issue.  Here is the debug output
when run with the latest version:

_________________________________________________________________________________
Spawned 'ssh -l admin batista'
        spawn id(5)
        Pid: 30003
        Tty: /dev/pts/4
 at /usr/lib/perl5/site_perl/5.8.6/Expect.pm line 179
        Expect::spawn('Expect', 'ssh -l admin batista') called at bug_15725
line 18
Starting EXPECT pattern matching...
 at /usr/lib/perl5/site_perl/5.8.6/Expect.pm line 559
        Expect::expect('Expect=GLOB(0x8da4ddc)', 30, 'passphrase') called at
bug_15725 line 22
spawn id(5): list of patterns:
  #1: -ex `passphrase'


spawn id(5): Does `'
match:
  pattern #1: -ex `passphrase'? No.

Waiting for new data (30 seconds)...
Enter passphrase for key '/root/.ssh/id_dsa':
spawn id(5): Does `Enter passphrase for key \'/root/.ssh/id_dsa\': '
match:
  pattern #1: -ex `passphrase'? YES!!
    Before match string: `Enter '
    Match string: `passphrase'
    After match string: ` for key \'/root/.ssh/id_dsa\': '
    Matchlist: ()
Returning from expect successfully.
...recieved password prompt
Sending 'password\n' to spawn id(5)
 at /usr/lib/perl5/site_perl/5.8.6/Expect.pm line 1248
        Expect::print('Expect=GLOB(0x8da4ddc)', 'password\x{a}') called at
bug_15725 line 27
Starting EXPECT pattern matching...
 at /usr/lib/perl5/site_perl/5.8.6/Expect.pm line 559
        Expect::expect('Expect=GLOB(0x8da4ddc)', 30, '/# ') called at
bug_15725 line 28
spawn id(5): list of patterns:
  #1: -ex `/# '


spawn id(5): Does ` for key \'/root/.ssh/id_dsa\': '
match:
  pattern #1: -ex `/# '? No.

Waiting for new data (30 seconds)...


spawn id(5): Does ` for key \'/root/.ssh/id_dsa\': \r\n'
match:
  pattern #1: -ex `/# '? No.

Waiting for new data (30 seconds)...
Last login: CLI on Tue Jul 25 15:05:45 2006 from 10.0.2.229

Custom OS v3.5
Copyright (c) 2000-2006 Some Company, Inc.  All Rights Reserved.

Welcome to Custom OS


spawn id(5): Does ` for key \'/root/.ssh/id_dsa\': \r\nLast login: CLI on
Tue Jul 25 15:05:45 2006 from 10.0.2.229\r\n\r\nCustom OS
v3.5\r\nCopyright(c) 2000-2006 Some Company Inc.  All Rights
Reserved.\r\n\r\nWelcome to
Custom OS\r\n\r\n'
match:
  pattern #1: -ex `/# '? No.

Waiting for new data (30 seconds)...
admin@batista:/#
spawn id(5): Does ` for key \'/root/.ssh/id_dsa\': \r\nLast login: CLI on
Tue Jul 25 15:05:45 2006 from 10.0.2.229\r\n\r\nCustom OS
v3.5\r\nCopyright(c) 2000-2006 Some Company, Inc.  All Rights
Reserved.\r\n\r\nWelcome to
Custom OSr\n\r\nadmin@batista:/# '
match:
  pattern #1: -ex `/# '? YES!!
    Before match string: ` for key \'/root/.ssh/id_dsa\': \r\nLast login:
CLI on Tue Jul 25 15:05:45 2006 from 10.0.2.229\r\n\r\nCustom OS
v3.5\r\nCopyright (c) 2000-2006 Some Company, Inc.  All Rights
Reserved.\r\n\r\nWelcome to Custom OS\r\n\r\nadmin@batista:'
    Match string: `/# '
    After match string: `'
    Matchlist: ()
Returning from expect successfully.
Sending 'sys hard\n' to spawn id(5)
 at /usr/lib/perl5/site_perl/5.8.6/Expect.pm line 1248
        Expect::print('Expect=GLOB(0x8da4ddc)', 'sys hard\x{a}') called at
bug_15725 line 32
Starting EXPECT pattern matching...
 at /usr/lib/perl5/site_perl/5.8.6/Expect.pm line 559
        Expect::expect('Expect=GLOB(0x8da4ddc)', 30, '/# ') called at
bug_15725 line 33
spawn id(5): list of patterns:
  #1: -ex `/# '


spawn id(5): Does `'
match:
  pattern #1: -ex `/# '? No.

Waiting for new data (30 seconds)...
sys hard

spawn id(5): Does `sys hard\r\n'
match:
  pattern #1: -ex `/# '? No.

Waiting for new data (30 seconds)...
Connection to batista closed.

spawn id(5): Does `sys hard\r\nConnection to batista closed.\r\r\n'
match:
  pattern #1: -ex `/# '? No.

Waiting for new data (30 seconds)...
Returning from expect with TIMEOUT or EOF
Error 03::Never got sec prompt, 3:Child PID 30003 exited with status 0
_________________________________________________________________________________

Here is the source to the script I am using in case that will help.

_________________________________________________________________________________
#!/usr/bin/perl -w

use strict;
use Expect;

my $username = "admin";
my $password = "password\n";

##### flip this value to 0 to turn off stout and 1 to turn it on
$Expect::Log_Stdout=1;

# Lets see what expect is doing!
$Expect::Exp_Internal = 1;
#$Expect::Debug = 3;

my $terminal = new Expect;
$terminal->raw_pty(1);
$terminal = Expect->spawn("ssh -l $username batista");

$terminal->log_file("test_err.txt");

unless ($terminal->expect(30,"passphrase")) {
   die "Error 01::Never got password prompt, ".$terminal->exp_error()."\n";
}
print "...recieved password prompt\n";

$terminal->send($password);
unless ($terminal->expect(30, '/# ')) {
   die "Error 02::Never got first prompt, ".$terminal->exp_error()."\n";
}

$terminal->send("sys hard\n");
unless ($terminal->expect(30, '/# ')) {
   die "Error 03::Never got sec prompt, ".$terminal->exp_error()."\n";
}

$terminal->send("exit\n");
$terminal->log_file(undef);
_________________________________________________________________________________

This session does work normally from a cli ssh session and works fine using
TCL expect and Python expect, just not perl expect.  I think I have nailed
down the location of the issue.  It is the sysread() call on or around line
832 (v 1.20).  After matching on the first promt and sending the "sys hard"
command to the remote server this sysread call only reads back the echoed
command and then detects 0 bytes read ($nread) and translates that to an EOF
and does a hard close:

$nread = 0 unless defined ($nread);
if ($nread == 0) {
   ...
   ...
   blah
   $exp->hard_close();
}

So it is the expect module that is sending the hard close to the distant
end.  The question is why does it not read the correct data from the socket
and continue to try and match?  The only thing it sees back once the sys
hard command is sent is the sys hard command and then text saying the
connection has been terminiated.






On 7/25/06, Roland Giersig <RGi...@cp...> wrote:
>
> Hi Eric,
>
> please upgrade to the latest Expect version (1.20), as you obviously
> have a version where _make_readable() doesn't work. :-( I'm sure that
> the debug output will make much more sense then... ;-)
>
> Ah, yes, and sorry to all for that mistake! That blunder was a good case
> to show that you always should follow the procedure: first create a
> testcase for the bug, showing the bug in the old version. Then fix it
> and test it with the testcase...
>
> Cheers! Roland
>
> > spawn id(5): Does `'
> > match:
> >   pattern #1: -ex `'? YES!!
> >     Before match string: `'
> >     Match string: `'
> >     After match string: `'
> >     Matchlist: ()
>
> --
> RGi...@cp...
>

Re: [Expectperl-discuss] Expect issues with custom OpenBSD and application interaction.

[Roland G. <RGi...@cp...>]

Hi Eric,

there must be some other reason, it's definitively not Expect:

> spawn id(5): Does `sys hard\r\nConnection to batista closed.\r\r\n'

This clearly indicates that the ssh connection was lost on its own and
Expect got the EOF as a result of that.

But I have no idea where that could come from, sorry...
[a hunch: maybe some issue with "\r" versus "\n", try send("sys
hard\r")]

Regards, Roland
--
RGi...@cp...

Re: [Expectperl-discuss] Expect issues with custom OpenBSD and application interaction.

[Eric T. <zi...@gm...>]

In the following debug statement:
spawn id(5): Does `sys hard\r\n'
match:
  pattern #1: -ex `/# '? No.

It shows that expect is reading back a \r\n (CR and a LF) when it is only
sent with a \n (LF).  Is there some sort of terminal translation that may be
adding this extra bit on?  \r\n as far as I know is only used by Windows
based platforms.  On Linux and BSD only thr LF is used (\n).

I am assuming that it is some sort of tty or pty issue, could you offer some
guidance in that area?  Plus the "Connection was closed" message is returned
to the client when the connection is lost.  It does not really denote which
side initiated it.  I do know that sysread is failing to read from the
socket which is causing $nread to be null which is causing $nread to be set
to 0 which is causing the hard_close to be called.  How can this not be an
expect issue if all this is already known?

Plus the fact that tcl expect and python expect as well as a manual ssh
session via cli all work as they are suppose to, to me means that it has to
be something in perl expect.

On 7/25/06, Roland Giersig <RGi...@cp...> wrote:
>
> Hi Eric,
>
> there must be some other reason, it's definitively not Expect:
>
> > spawn id(5): Does `sys hard\r\nConnection to batista closed.\r\r\n'
>
> This clearly indicates that the ssh connection was lost on its own and
> Expect got the EOF as a result of that.
>
> But I have no idea where that could come from, sorry...
> [a hunch: maybe some issue with "\r" versus "\n", try send("sys
> hard\r")]
>
> Regards, Roland
> --
> RGi...@cp...
>

Re: [Expectperl-discuss] Expect issues with custom OpenBSD and application interaction.

[Eric T. <zi...@gm...>]

The issue was discovered,  On the distant end of my connection there was
some interaction with psh and perl expect was sending a window size of (0,
0) and libedit, which is used by psh, did not like that.  A workaround was
to set the clone_winsize_from to STDIN.

$exp->slave->clone_winsize_from(\*STDIN);

Just for reference in case anyone else ever has this issue...

On 7/25/06, Eric Thompson <zi...@gm...> wrote:
>
> In the following debug statement:
> spawn id(5): Does `sys hard\r\n'
>
> match:
>   pattern #1: -ex `/# '? No.
>
> It shows that expect is reading back a \r\n (CR and a LF) when it is only
> sent with a \n (LF).  Is there some sort of terminal translation that may be
> adding this extra bit on?  \r\n as far as I know is only used by Windows
> based platforms.  On Linux and BSD only thr LF is used (\n).
>
> I am assuming that it is some sort of tty or pty issue, could you offer
> some guidance in that area?  Plus the "Connection was closed" message is
> returned to the client when the connection is lost.  It does not really
> denote which side initiated it.  I do know that sysread is failing to read
> from the socket which is causing $nread to be null which is causing $nread
> to be set to 0 which is causing the hard_close to be called.  How can this
> not be an expect issue if all this is already known?
>
> Plus the fact that tcl expect and python expect as well as a manual ssh
> session via cli all work as they are suppose to, to me means that it has to
> be something in perl expect.
>
> On 7/25/06, Roland Giersig <RGi...@cp...> wrote:
>
> > Hi Eric,
> >
> > there must be some other reason, it's definitively not Expect:
> >
> > > spawn id(5): Does `sys hard\r\nConnection to batista closed.\r\r\n'
> >
> > This clearly indicates that the ssh connection was lost on its own and
> > Expect got the EOF as a result of that.
> >
> > But I have no idea where that could come from, sorry...
> > [a hunch: maybe some issue with "\r" versus "\n", try send("sys
> > hard\r")]
> >
> > Regards, Roland
> > --
> > RGi...@cp...
> >
>
>