Error reading from socket

[emildayan]

Hi,

PHPSeclib: 3.0.21

Connecting to a remote Cisco using username/password.
Timeout is set very high, so that's not the issue.

Running the command show mac address-table | no-more which has a pretty length output.

The error comes from phpseclib3\Net\SSH2->read_remaining_bytes()

Similar issue as #1700
Here is the output @terrafrost wanted then:

{
    "timed_out": false,
    "blocked": true,
    "eof": false,
    "stream_type": "tcp_socket\/ssl",
    "mode": "r+",
    "unread_bytes": 0,
    "seekable": false
}
{
    "timed_out": false,
    "blocked": true,
    "eof": false,
    "stream_type": "tcp_socket\/ssl",
    "mode": "r+",
    "unread_bytes": 16,
    "seekable": false
}
{
    "timed_out": false,
    "blocked": true,
    "eof": false,
    "stream_type": "tcp_socket\/ssl",
    "mode": "r+",
    "unread_bytes": 0,
    "seekable": false
}
{
    "timed_out": false,
    "blocked": true,
    "eof": false,
    "stream_type": "tcp_socket\/ssl",
    "mode": "r+",
    "unread_bytes": 16,
    "seekable": false
}
{
    "timed_out": false,
    "blocked": true,
    "eof": false,
    "stream_type": "tcp_socket\/ssl",
    "mode": "r+",
    "unread_bytes": 100,
    "seekable": false
}
{
    "timed_out": false,
    "blocked": true,
    "eof": false,
    "stream_type": "tcp_socket\/ssl",
    "mode": "r+",
    "unread_bytes": 16,
    "seekable": false
}
{
    "timed_out": false,
    "blocked": true,
    "eof": false,
    "stream_type": "tcp_socket\/ssl",
    "mode": "r+",
    "unread_bytes": 16,
    "seekable": false
}
{
    "timed_out": false,
    "blocked": true,
    "eof": false,
    "stream_type": "tcp_socket\/ssl",
    "mode": "r+",
    "unread_bytes": 16,
    "seekable": false
}
{
    "timed_out": false,
    "blocked": true,
    "eof": false,
    "stream_type": "tcp_socket\/ssl",
    "mode": "r+",
    "unread_bytes": 16,
    "seekable": false
}
{
    "timed_out": false,
    "blocked": true,
    "eof": false,
    "stream_type": "tcp_socket\/ssl",
    "mode": "r+",
    "unread_bytes": 52,
    "seekable": false
}
{
    "timed_out": false,
    "blocked": true,
    "eof": false,
    "stream_type": "tcp_socket\/ssl",
    "mode": "r+",
    "unread_bytes": 16,
    "seekable": false
}
{
    "timed_out": false,
    "blocked": true,
    "eof": false,
    "stream_type": "tcp_socket\/ssl",
    "mode": "r+",
    "unread_bytes": 16,
    "seekable": false
}
{
    "timed_out": false,
    "blocked": true,
    "eof": false,
    "stream_type": "tcp_socket\/ssl",
    "mode": "r+",
    "unread_bytes": 972,
    "seekable": false
}
{
    "timed_out": false,
    "blocked": true,
    "eof": false,
    "stream_type": "tcp_socket\/ssl",
    "mode": "r+",
    "unread_bytes": 480,
    "seekable": false
}
{
    "timed_out": false,
    "blocked": true,
    "eof": false,
    "stream_type": "tcp_socket\/ssl",
    "mode": "r+",
    "unread_bytes": 1436,
    "seekable": false
}
{
    "timed_out": false,
    "blocked": true,
    "eof": false,
    "stream_type": "tcp_socket\/ssl",
    "mode": "r+",
    "unread_bytes": 944,
    "seekable": false
}
{
    "timed_out": false,
    "blocked": true,
    "eof": false,
    "stream_type": "tcp_socket\/ssl",
    "mode": "r+",
    "unread_bytes": 452,
    "seekable": false
}
{
    "timed_out": false,
    "blocked": true,
    "eof": false,
    "stream_type": "tcp_socket\/ssl",
    "mode": "r+",
    "unread_bytes": 1408,
    "seekable": false
}
{
    "timed_out": false,
    "blocked": true,
    "eof": false,
    "stream_type": "tcp_socket\/ssl",
    "mode": "r+",
    "unread_bytes": 916,
    "seekable": false
}
{
    "timed_out": false,
    "blocked": true,
    "eof": false,
    "stream_type": "tcp_socket\/ssl",
    "mode": "r+",
    "unread_bytes": 184,
    "seekable": false
}
{
    "timed_out": false,
    "blocked": true,
    "eof": false,
    "stream_type": "tcp_socket\/ssl",
    "mode": "r+",
    "unread_bytes": 1140,
    "seekable": false
}
{
    "timed_out": false,
    "blocked": true,
    "eof": false,
    "stream_type": "tcp_socket\/ssl",
    "mode": "r+",
    "unread_bytes": 648,
    "seekable": false
}
feof
{
    "timed_out": false,
    "blocked": true,
    "eof": true,
    "stream_type": "tcp_socket\/ssl",
    "mode": "r+",
    "unread_bytes": 0,
    "seekable": false
}

I have emailed the full log with NET_SSH2_LOGGING as I cannot share potentially sensitive data.
In the log, I see parts of the contents from the command - so from my understanding it's reading correctly but cannot get the full response.

[terrafrost]

So I guess you're using a Juniper router?

Anyway, normally when an SSH server is done sending the output of a command it sends NET_SSH2_MSG_CHANNEL_EOF
and NET_SSH2_MSG_CHANNEL_REQUEST. Yours doesn't appear to be doing that. That said, the "Error reading from socket" error is weird. I can't discern what's up with that from the logs but maybe you can modify your code thusly to help me get to the bottom of it?:

#
#-----[ OPEN ]------------------------------------------
#
Net/SSH2.php
#
#-----[ FIND ]------------------------------------------
#
                    $this->decrypt->setAAD($temp = Strings::shift($raw, 4));
                    extract(unpack('Npacket_length', $temp));
                    /**
                     * @var integer $packet_length
                     */

                    $raw .= $this->read_remaining_bytes($packet_length - $this->decrypt_block_size + 4);
#
#-----[ REPLACE WITH ]----------------------------------
#
                    $this->decrypt->setAAD($temp = Strings::shift($raw, 4));
                    extract(unpack('Npacket_length', $temp));
                    /**
                     * @var integer $packet_length
                     */

try {
                    $raw .= $this->read_remaining_bytes($packet_length - $this->decrypt_block_size + 4);
} catch (\Exception $e) {
echo "packet_length = $packet_length\ndecrypt_block_size = {$this->decrypt_block_size}\n";
    throw $e;
}
#
#-----[ FIND ]------------------------------------------
#
            if ($temp === false || feof($this->fsock)) {
                $this->disconnect_helper(NET_SSH2_DISCONNECT_CONNECTION_LOST);
                throw new \RuntimeException('Error reading from socket');
            }
#
#-----[ REPLACE WITH ]----------------------------------
#
            if ($temp === false || feof($this->fsock)) {
echo "remaining length = $remaining_length\n";
                $this->disconnect_helper(NET_SSH2_DISCONNECT_CONNECTION_LOST);
                throw new \RuntimeException('Error reading from socket');
            }

In lieu of knowing the output of that I wonder if doing the above with a PTY ($ssh->enablePTY() ) or with an interactive shell (eg. $ssh->read('[prompt]'); $ssh->write("command\n"); echo $ssh->read('[prompt]');) would help.

[emildayan]

Hi,

Super frustrating, but this 'automatically' solved itself.
I got the same error when running the command to 16 different Cisco-routers, all failing.
Now, without any changes, all are passing.

Not sure if the length of the output (as ARP table changes) has any effect.
What I do know is if I ran a shorter command (eg show clock), it would pass just fine.

I'll go ahead and try your code and post output if the problem arise.

"A bug that disappears on its own will come back on its own" - so I'll be back eventually..

[emildayan]

Hi,

So this keep happening very randomly, and to more than Cisco-routers.
I can't reproduce it thus it seems very random, but have it happening 5-6 times per day on various SSH-commands to various remote servers.

Do you want me to add any snippet anywhere to capture more data?
Tricky thing is it works 99.99% of all the commands (we send tens of thousands daily), so we don't want to interfere with those if possible.

Thanks,
Emil

[terrafrost]

Did you try adding the code I mentioned in #1946 (comment) ?

Re-reviewing the logs you sent me, the server identifies itself as using OpenSSH. Can you edit the sshd_config file? If so could you add the following to it?:

SyslogFacility LOCAL0
LogLevel Debug3

Then, when you get the error, if you could get the logs for that session and send them to me that could yield some useful insights.

[emildayan]

This started happening now pretty frequently so managed to capture logs.
I will send you the raw email logs (as it could contain sensitive data that don't belong on Github).

Here is the output of the code echo:
remaining length = 13940
packet_length = 13952
decrypt_block_size = 16

This is not with adjusted loglevel on the server (which I cannot change at the moment).
If that's absolutely necessary let me know and we'll schedule a planned maintenance.

Thank you!

[terrafrost]

I'm going to need access to the server to figure this out.

Right now I'm on a plane flying to Europe from Texas for the start of a two week long vacation.

To figure this out is going to require a lot of trial and error. Like let's say I gave you some more changes to run in the morning and then after I'm finished seeing the northern lights or whatever, I'd have to get back into this - like I'd have to get into the same headspace that I was when I made code change requests and I don't want that to be a key defining characteristic of this trip. I'd rather just get in, spend a few hours on it one night after I get back from whatever activity I'm doing and figure it out and then be done with it rather then having it hanging over my shoulders for the entire length of my vacay.

[emildayan]

Hi,

First off - enjoy your trip. Don't in any way let this ticket get in the way of that.

Secondly - granting access will be impossible as it's a bastion server, meaning it has no internet and only talks locally to other servers on the lan.

I understand this makes it a ton more difficult to troubleshoot.
Seeing as it's intermittient (every 15th request or so, randomly) I could just wrap it in a try/catch with a retry if you feel like it's an hard-to-reproduce ticket.

Enjoy Europe and don't stress over this ticket, please.