Exception: Expected NET_SFTP_VERSION. Got packet type:

[SchalkBreedSF]

I sometimes get an Exception but don't really know why

Expected NET_SFTP_VERSION. Got packet type: 

It seems sometimes when the get() function is called, somehow the $this->packet_type is empty?

I do not know how I can give more info. The exception does not come back consistently.
Any ideas on why the exception would occur would be helpful :)

Function used

$ftp->get($file_from, $file_to);

[terrafrost]

If you could enable logging (define('NET_SSH2_LOGGING', 2);) at the top of the file and then catch the exception and, when caught, do echo $ssh->getLog(); that'd be cool. That'd let me actually see what's going on.

Thanks!

[SchalkBreedSF]

Hi @terrafrost

I am trying to get logs from a live environment but it seems to not output everything (This could be part of the problem?)

-> NET_SFTP_INIT (0.0001s) 00000000  00:00:00:03                                      ....   

That is the whole thing. This is when it fails, it does not fail all the time. When it fails, all we get is

Expected NET_SFTP_VERSION. Got packet type:  

No value to packet type.

How I output:

define('NET_SFTP_LOGGING', SFTP::LOG_COMPLEX);
try {
    if ($ftp->connect()) {
    // Code to do FTP stuff
    }
} catch (Exception $e) {
    print_r($ftp->getSFTPLog());
    $ftp->disconnect();
    $error = $e->getMessage(); //Error message would be the NET_SFTP_VERSION one mentioned above
}

Why would the logs be empty?

[terrafrost]

It's possible the SSH server is killing the connection. Could you do SSH logging (define('NET_SSH2_LOGGING', SSH2::LOG_COMPLEX)) instead of SFTP logging? There might be additional SSH2 packets after the SFTP packets (which are themselves contained within SSH2 packets) which might provide some insight.

It's also possible the SSH server is straight up killing the connection. The SSH logs would show me the server identification string. Like are you connecting to an OpenSSH server or some proprietary SSH server? Proprietary SSH servers are more likely to have bugs. Also, if it were OpenSSH and if it were a server you had full control over I could give you further directions to help diagnose what's going on if the SSH logs didn't yield any insights.

[SchalkBreedSF]

@terrafrost How can I get the log to you without posting it here? Just want to be cautious with the info.
Note: We also have access to the server should additional info be required.

[terrafrost]

You can email the logs to ***@***.*** Thanks!

…

On Wed, May 18, 2022, 10:01 AM Schalk ***@***.***> wrote: @terrafrost <https://github.com/terrafrost> How can I get the log to you without posting it here? Just want to be cautious with the info. Note: We also have access to the server should additional info be required. — Reply to this email directly, view it on GitHub <#1793 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AABULSTLS56I4JRYBBZFZHDVKUA3PANCNFSM5VQ6J46A> . You are receiving this because you were mentioned.Message ID: ***@***.***>

[SchalkBreedSF]

@terrafrost For some reason I can't see that email... It shows ***@***.***

[terrafrost]

Oh. I guess github replaces emails with that when replies are sent via email.

Anyway, the email is terrafrost@php.net.

Thanks!

[terrafrost]

I got the logs - thanks! I'll take a look this evening or tomorrow as time permits!

[fcaps]

Hey guys,
we got the same issue, any updates?
can we help somehow?

[terrafrost]

can we help somehow?

Get logs by doing define('NET_SSH2_LOGGING', SSH2::LOG_COMPLEX) at the top and then echo $ssh->getLog() after and then either post them or email to me at terrafrost@php.net.

we got the same issue, any updates?

The OP's issue got more fleshed out over email. At one point he said this:

What is weird is that it is working most of the time without issue, and only sometimes (on the hour) do we get the empty packet error. It's not like it's persisting for long periods of time

I posted about it on the OpenSSH mailing lists:

https://lists.mindrot.org/pipermail/openssh-unix-dev/2021-October/039773.html

Quoting some of the responses I got:

If you can catch it when it's in the stalled state, I'd check the netstat entry corresponding to the sshd to see if there's anything in the "SendQ" (which would indicate a problem with the network) and strace the sshd and sftp-server processes to see what if anything they're waiting on.

The "on the hour" nature of it makes me suspicious, though. Do you do anything like roll the syslogs on the hour?

Also:

The problem could be quite far away. Such as for some reason the firewall rules being reloaded at the top of every hour and for just a very short time hourly it could be blocking packets.

Try disabling cron and/or systemd-timerd (I think on Ubuntu?) and see if things magically work at the top of the hour? If so then it is something happening via those other periodic tasks.

I sent these responses to the OP and never heard back. But TLDR the OPs issue doesn't seem to be either a phpseclib or OpenSSH issue but an issue that lies elsewhere.

[fcaps]

Thanks!
We will try to find something, but in our case this only occurs every 10-20 days, hard to inspect.

[fcaps]

So, we finally got some logs.

Stuff that can be relevant:

• there could be multiple session open to this ftp-server (even with the same ftp-user)
• server is an aws transfer family product
• other servers/clients could also use this user to connect

First example:

[2022-08-17 14:30:24] production.DEBUG: [SshLog] <-
00000000  53:53:48:2d:32:2e:30:2d:41:57:53:5f:53:46:54:50  SSH-2.0-AWS_SFTP
00000010  5f:31:2e:31:0d:0a                                _1.1..
->
00000000  53:53:48:2d:32:2e:30:2d:70:68:70:73:65:63:6c:69  SSH-2.0-phpsecli
00000010  62:5f:33:2e:30:20:28:6c:69:62:73:6f:64:69:75:6d  b_3.0 (libsodium
00000020  2c:20:6f:70:65:6e:73:73:6c:2c:20:67:6d:70:29:0d  , openssl, gmp).
00000030  0a    

(removed auth log )

<- NET_SSH2_MSG_USERAUTH_SUCCESS (since last: 0.5334, network: 0.5334s)
-> NET_SSH2_MSG_CHANNEL_OPEN (since last: 0.0002, network: 0.0001s)
00000000  00:00:00:07:73:65:73:73:69:6f:6e:00:00:01:00:7f  ....session.....
00000010  ff:ff:ff:00:00:40:00                             .....@.
<- NET_SSH2_MSG_GLOBAL_REQUEST (since last: 0.0018, network: 0.0001s)
00000000  00:00:00:17:68:6f:73:74:6b:65:79:73:2d:30:30:40  ....hostkeys-00@
00000010  6f:70:65:6e:73:73:68:2e:63:6f:6d:00:00:00:01:17  openssh.com.....
00000020  00:00:00:07:73:73:68:2d:72:73:61:00:00:00:03:01  ....ssh-rsa.....

(removed hostkeys sync)

-> NET_SSH2_MSG_REQUEST_FAILURE (since last: 0.0001, network: 0.0001s)
<- NET_SSH2_MSG_CHANNEL_OPEN_CONFIRMATION (since last: 0.0019, network: 0.0001s)
00000000  00:00:01:00:00:00:00:00:00:00:00:00:00:00:80:00  ................
-> NET_SSH2_MSG_CHANNEL_REQUEST (since last: 0.0001, network: 0.0001s)
00000000  00:00:00:00:00:00:00:09:73:75:62:73:79:73:74:65  ........subsyste
00000010  6d:01:00:00:00:04:73:66:74:70                    m.....sftp
<- NET_SSH2_MSG_CHANNEL_WINDOW_ADJUST (since last: 0.0019, network: 0.0001s)
00000000  00:00:01:00:00:20:00:00                          ..... ..
<- NET_SSH2_MSG_CHANNEL_SUCCESS (since last: 0.0001, network: 0s)
00000000  00:00:01:00                                      ....
-> NET_SSH2_MSG_CHANNEL_DATA (since last: 0.0001, network: 0s)
00000000  00:00:00:00:00:00:00:09:00:00:00:05:01:00:00:00  ................
00000010  03                                               .
[2022-08-17 14:30:24] production.ERROR: Expected NET_SFTP_VERSION. Got packet type:

[terrafrost]

One possibility is that there was a time consuming packet in one part of the logs that I am unable to see. In that scenario, doing $ssh->setTimeout(0) should help. But it's also just as possible that the server is just killing the connection for reasons unknown. Like maybe it's a server bug or maybe, as discussed in #1793 (comment), there's something else concurrently going on, completely unrelated to phpseclib, that's interfering with the connection. I've never messed around with AWS Transfer Family but I know with AWS RDS / Aurora instances backups are made at a certain time and there are also maintenance windows. If you were trying to connect during either of those, who knows, maybe that'd explain the issue you're seeing.

I have an AWS account that I can try to set AWS Transfer Family up on and see what that offers, in-so-far as server-side logging goes, but, based on the logs, I'm not sure there's anything phpseclib can really do as it kinda seems to me like it's an issue with the server.

Once I setup AWS Transfer Family I can try to reproduce the issue, as well, but if you're saying it only happens every 10-20 days even that could be tricky.

How often are you doing the transfers? Is it daily? Multiple times a day? If you only attempt to use phpseclib to transfer files every 10-20 days and every time you make such an attempt you encounter this error then, at that point, it seems like it would be fairly easy to reproduce, but if, over the course of 10-20 days, you make 1,000,000+ connections with phpseclib and only 1 of them fails out of the 1,000,000+ that it successfully does, then I'm not sure there's a whole lot i could do!

[fcaps]

How often are you doing the transfers?

Hard to estimate, but calling SFTP:rawlist min. 48 times a day (every 30min).
Doing SFTP::stat & ::get & ::delete every now and then but estimated 300 times a month (0-50 a day).
Finally uploading files 300 times month.

then I'm not sure there's a whole lot i could do!

It's super hard to reproduce, we tried it.
Maybe something like a long running test with multiple sessions that "mess" with each other. deleting partial-files, setstat, uploading and directly deleting etc.

Some other hints:

• someone was telling us he had the "same" error, and it was something with the channel-size (server vs client) -> they did not fix it, just swapped directly aws->s3
• in our case the "other" party is uploading files, and we are downloading + deleting them -> don't know much about the client they are using
• the error only occurs (at least till now) if we got a spike in uploads/downloads from the other party -> active at the same time
• the error already occurred multiple times a day, and i cannot find a pattern related to a specific time or day
• the other party never had an issue, or never told us they had one. -> we asked them a couple days ago, still no answer
• found something in the aws doc related to "Avoid setstat errors", but we don't do that?. maybe the other party is calling setstat
• also found something about multiple-connection upload is not supported in the docs-> don't know if this is relevant

https://docs.aws.amazon.com/transfer/latest/userguide/transferfamily-ug.pdf

Thank you very much for your time!

[Nikoslav]

I have the same issue, but can reproduce it every time. Started happening after sftp server was upgraded. I can login to the server from CLI without issues.
OS: Debian 11
PHPseclib version: 3.0.17

Code snippet:

define('NET_SFTP_LOGGING', SFTP::LOG_COMPLEX);
define('NET_SSH2_LOGGING', SSH2::LOG_COMPLEX);
			try {
				$ftpConn = new SFTP($host, $port);
                                $ftpConn->setTimeout(0);
				$ftpConn->login($User, $Pass);
                                $tempfiles = $ftpConn->nlist('.');
			} catch (Exception $exc) {
				echo $exc->getMessage()."\n";
                                echo $exc->getTraceAsString()."\n";
                        }

Expected NET_SFTP_VERSION. Got packet type:
#0 /home/monitor/test/vendor/phpseclib/phpseclib/phpseclib/Net/SFTP.php(635): phpseclib3\Net\SFTP->partial_init_sftp_connection()
#1 /home/monitor/test/vendor/phpseclib/phpseclib/phpseclib/Net/SFTP.php(532): phpseclib3\Net\SFTP->init_sftp_connection()
#2 /home/monitor/test/vendor/phpseclib/phpseclib/phpseclib/Net/SFTP.php(1094): phpseclib3\Net\SFTP->precheck()
#3 /home/monitor/test/vendor/phpseclib/phpseclib/phpseclib/Net/SFTP.php(1004): phpseclib3\Net\SFTP->readlist()
#4 /home/monitor/test/vendor/phpseclib/phpseclib/phpseclib/Net/SFTP.php(991): phpseclib3\Net\SFTP->nlist_helper()
#5 /home/monitor/test/ims.inc.php(64): phpseclib3\Net\SFTP->nlist()
#6 {main}
-> NET_SFTP_INIT (0s)
00000000  00:00:03                                         ...

Help please:)

[Nikoslav]

SFTP server admin changed the config(would not say how) and now it works fine. Thanks!

[ikudosi]

I've been experiencing this issue for awhile now. The SFTP I connect to is AWS Transfer Family where it's hooked up to an S3. It doesn't happen all the time but I do see it occur every couple of days... which I can't understand.

[terrafrost]

@ikudosi - sorry for not responding sooner - I guess I didn't see this. As a general rule, it's easier to spot new tickets vs new replies.

Anyway, if you could get me the SSH2 logs that'd be helpful. You can get them by doing define('NET_SSH2_LOGGING', SSH2::LOG_COMPLEX) at the top and then echo $ssh->getLog() after you have the issue.

Thanks!