Debugging Net::SSH Protocol Error

[cmv]

Monks-

This error has been looming for quite a while, and it has just recently hit-the-fan for me.

If anybody has a solution, please speak up.

I am attempting to debug, and am using this note to document my progress. Any help or suggestions is much appreciated!

-Craig

I am running with perl v5.8.8 built for darwin using the following:

Module id = Net::SSH::Perl
    CPAN_USERID  SCHWIGON (Steffen Schwigon <[e-mail]>)
    CPAN_VERSION 2.01
    CPAN_FILE    S/SC/SCHWIGON/Net-SSH-Perl-2.01.tar.gz
    MANPAGE      Net::SSH::Perl - Perl client Interface to SSH
    INST_FILE    /opt/exp/perl/perl5.8/lib/site_perl/5.8.8/Net/SSH/Per
+l.pm
    INST_VERSION 1.34

The exact error message I get is as follows:

XS_Tk__Callback_Call error:Protocol error: expected packet type 91, go
+t 80 at /opt/exp/perl/perl5.8/lib/site_perl/5.8.8/Net/SSH/Perl/Packet
+.pm line 222

Tk::Error: Protocol error: expected packet type 91, got 80 at /opt/exp
+/perl/perl5.8/lib/site_perl/5.8.8/Net/SSH/Perl/Packet.pm line 224
 Carp::croak at /opt/exp/perl/perl5.8/lib/5.8.8/Carp.pm line 269
 Net::SSH::Perl::fatal_disconnect at /opt/exp/perl/perl5.8/lib/site_pe
+rl/5.8.8/Net/SSH/Perl.pm line 255
 Net::SSH::Perl::Packet::read_expect at /opt/exp/perl/perl5.8/lib/site
+_perl/5.8.8/Net/SSH/Perl/Packet.pm line 224
 Net::SSH::Perl::SSH2::login at /opt/exp/perl/perl5.8/lib/site_perl/5.
+8.8/Net/SSH/Perl/SSH2.pm line 78
 Auth::sshKeys::SetupKeys at lib/Auth/sshKeys.pm line 154
 remExec::SetupSSH at lib/remExec.pm line 161
 PCMDtrace::_runCmd at lib/PCMDtrace.pm line 657
 PCMDtrace::StatusUpdate at lib/PCMDtrace.pm line 138
 Ui::winTrace::_displayStatus at lib/Ui/winTrace.pm line 788
 Ui::winTrace::__ANON__ at lib/Ui/winTrace.pm line 176
 Tk::Widget::Callback at /opt/exp/perl/perl5.8/lib/site_perl/5.8.8/dar
+win/Tk/Widget.pm line 1156
 Tk::Optionmenu::setOption at /opt/exp/perl/perl5.8/lib/site_perl/5.8.
+8/darwin/Tk/Optionmenu.pm line 72
 Tk callback for .frame.optionmenu.menu
 Tk::__ANON__ at /opt/exp/perl/perl5.8/lib/site_perl/5.8.8/darwin/Tk.p
+m line 251
 Tk::Menu::Invoke at /opt/exp/perl/perl5.8/lib/site_perl/5.8.8/darwin/
+Tk/Menu.pm line 532
 <ButtonRelease>
 (command bound to event)

Checking out Packet.pm I see line 222 in the following:

217 sub read_expect {
218     my $class = shift;
219     my($ssh, $type) = @_;
220     my $pack = $class->read($ssh);
221     if ($pack->type != $type) {
222         $ssh->fatal_disconnect(sprintf
223           "Protocol error: expected packet type %d, got %d",
224             $type, $pack->type);
225     }
226     $pack;
227 }

It seems that read_expect() in this case is being called from here:

caller DUMP:
$VAR1 = 'Net::SSH::Perl::SSH2';
$VAR2 = '/opt/exp/perl/perl5.8/lib/site_perl/5.8.8/Net/SSH/Perl/SSH2.p
+m';
$VAR3 = 78;

Going to SSH2.pm shows line 78 to look like this:

 65 sub login {
 66     my $ssh = shift;
 67     $ssh->SUPER::login(@_);
 68     my $suppress_shell = $_[2];
 69     $ssh->_login or $ssh->fatal_disconnect("Permission denied");
 70
 71     $ssh->debug("Login completed, opening dummy shell channel.");
 72     my $cmgr = $ssh->channel_mgr;
 73     my $channel = $cmgr->new_channel(
 74         ctype => 'session', local_window => 0,
 75         local_maxpacket => 0, remote_name => 'client-session');
 76     $channel->open;
 77
 78     my $packet = Net::SSH::Perl::Packet->read_expect($ssh,
 79         SSH2_MSG_CHANNEL_OPEN_CONFIRMATION);
 80     $cmgr->input_open_confirmation($packet);
 81
 82     unless ($suppress_shell) {
 83         $ssh->debug("Got channel open confirmation, requesting she
+ll.");
 84         $channel->request("shell", 0);
 85     }
 86 }

So we are in the process of logging in, and expecting to get a SSH2_MSG_CHANNEL_OPEN_CONFIRMATION (defined as 91 in constants.pm), but instead we are getting message 80, which is not defined in any of the Net:SSH:Perl code.

Google points me here to see a list of messages and see that message 80 is:

80        SSH_MSG_GLOBAL_REQUEST

Okay, why the heck are we getting this message in the middle of login? More googling leads me to IETF which states:

4.  Global Requests

   There are several kinds of requests that affect the state of the
   remote end globally, independent of any channels.  An example is a
   request to start TCP/IP forwarding for a specific port.  Note that
   both the client and server MAY send global requests at any time, an
+d
   the receiver MUST respond appropriately.

All such requests use the
   following format.

      byte      SSH_MSG_GLOBAL_REQUEST
      string    request name in US-ASCII only
      boolean   want reply
      ....      request-specific data follows

   The value of 'request name' follows the DNS extensibility naming
   convention outlined in [SSH-ARCH].

   The recipient will respond to this message with
   SSH_MSG_REQUEST_SUCCESS or SSH_MSG_REQUEST_FAILURE if 'want reply' 
+is
   TRUE.

      byte      SSH_MSG_REQUEST_SUCCESS
      ....     response specific data

   Usually, the 'response specific data' is non-existent.

   If the recipient does not recognize or support the request, it simp
+ly
   responds with SSH_MSG_REQUEST_FAILURE.

      byte      SSH_MSG_REQUEST_FAILURE

   In general, the reply messages do not include request type
   identifiers.  To make it possible for the originator of a request t
+o
   identify to which request each reply refers, it is REQUIRED that
   replies to SSH_MSG_GLOBAL_REQUESTS MUST be sent in the same order a
+s
   the corresponding request messages.  For channel requests, replies
   that relate to the same channel MUST also be replied to in the righ
+t
   order.  However, channel requests for distinct channels MAY be
   replied to out-of-order.

Huh, interesting. I didn't know about SSH global requests, but why is it making Net::SSH::Perl barf now?

More googling gets me to stackoverflow which seems to have a reasonable answer:

The message 80 stands for SSH_MSG_GLOBAL_REQUEST.

Modern versions of OpenSSH server use this generic message for various proprietary extensions of the SSH protocol.

Most clients will/should silently ignore unrecognized messages. The SSH.NET does ignore the SSH_MSG_GLOBAL_REQUEST too, but it does not expect the message until an authentication completes.

Unfortunately it seems that OpenSSH sends some of these (maybe the [e-mail]) even before the authentication.

The problem has been fixed in SSH.NET 2016.0.0-beta1. See Issue #8.

So it seems that a good hack might be to get Net::SSH::Perl to simply ignore all of these global requests.

Does that sound right? Any better suggestions?

[Mr. Muskrat]

Are you sure that you have version 2.01 of Net::SSH::Perl installed? Line 222 of Net::SSH::Perl::Packet is not the one you indicated.... https://metacpan.org/source/SCHWIGON/Net-SSH-Perl-2.01/lib/Net/SSH/Perl/Packet.pm#L222

It looks like you have something between versions 1.25 and 1.42.

[cmv]

Mr. Muskrat++

Thanks for the pointer. You are correct - I am not on version 2.01 as I thought.

Looking at the 2.01 code, they already have a fix in place for this issue.

I'm glad it was fixed!

-Craig

[cmv]

Folks-

This is a quick hack that seems to be working for me.

Suggestions on a better one would be welcome!

Thanks

-Craig

Editing .../Net/SSH/Perl/Packet.pm:

217 sub read_expect {
218     my $class = shift;
219     my($ssh, $type) = @_;
220     my $pack = $class->read($ssh);
221     while($pack->type == 80) {          # CMV Hack start vvvv
222 print STDERR "IGNORING GLOBAL MESSAGE...";
223        $pack = $class->read($ssh);
224 print STDERR " NEXT MESSAGE IS: ", $pack->type, "\n";
225     }                                   # CMV Hack end ^^^^
226     if ($pack->type != $type) {
227         $ssh->fatal_disconnect(sprintf
228           "Protocol error: expected packet type %d, got %d",
229             $type, $pack->type);
230     }
231     $pack;
232 }