SFTP Incremental Reads + Writes #725
Comments
|
All of the get/put/copy and wildcard mget/mput/mcopy functions should write data to the destination as soon as it is read in. The default block size used to be fixed at 16 KB and the max parallel requests at 128, so the most you should need is about 2 MB per file being transferred. If you transfer multiple files at once, this would be the amount needed per file. With AsyncSSH 2.18.0, the default buffer size can be higher if the server supports the "limit" extension and advertises a larger max read/write size, so on very large files you may see an increase in memory needed (up to something like 512 MB). If this is too much, though, you can either set a smaller block size or reduce the max number of parallel requests, though you may lose some speed depending on how small you make these. The arguments to control this are |
|
Hey @ronf, Really appreciate your input here. I played around with the DEBUG:asyncssh:[conn=20, chan=0] Sending 28 data bytes
DEBUG:asyncssh.sftp:[conn=20, chan=0] Sending read for 16384 bytes at offset 1052262400 in handle 313033
DEBUG:asyncssh:[conn=20, chan=0] Sending 28 data bytes
DEBUG:asyncssh.sftp:[conn=20, chan=0] Sending read for 16384 bytes at offset 1052278784 in handle 313033
DEBUG:asyncssh:[conn=20, chan=0] Sending 28 data bytes
DEBUG:asyncssh.sftp:[conn=20, chan=0] Sending read for 16384 bytes at offset 1052295168 in handle 313033
DEBUG:asyncssh:[conn=20, chan=0] Sending 28 data bytes
DEBUG:asyncssh:[conn=20, chan=0] Received 32720 data bytes
DEBUG:asyncssh:[conn=20, chan=0] Received 32720 data bytes
DEBUG:asyncssh:[conn=20, chan=0] Received 32720 data bytes
DEBUG:asyncssh:[conn=20, chan=0] Received 20921 data bytes
DEBUG:asyncssh:[conn=20] Requesting key exchange
DEBUG:asyncssh:[conn=20] Key exchange algs: curve25519-sha256,[email protected],curve448-sha512,ecdh-sha2-nistp521,ecdh-sha2-nistp384,ecdh-sha2-nistp256,ecdh-sha2-1.3.132.0.10,diffie-hellman-group-exchange-sha256,diffie-hellman-group14-sha256,diffie-hellman-group15-sha512,diffie-hellman-group16-sha512,diffie-hellman-group17-sha512,diffie-hellman-group18-sha512,[email protected],diffie-hellman-group14-sha1,rsa2048-sha256,ext-info-c,[email protected]
DEBUG:asyncssh:[conn=20] Host key algs: ssh-ed25519
DEBUG:asyncssh:[conn=20] Encryption algs: [email protected],[email protected],[email protected],aes256-ctr,aes192-ctr,aes128-ctr
DEBUG:asyncssh:[conn=20] MAC algs: [email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],hmac-sha2-256,hmac-sha2-512,hmac-sha1,[email protected],[email protected],[email protected],[email protected],[email protected]
DEBUG:asyncssh:[conn=20] Compression algs: none,[email protected]
DEBUG:asyncssh:[conn=20] Received key exchange request
DEBUG:asyncssh:[conn=20] Key exchange algs: curve25519-sha256,[email protected],diffie-hellman-group18-sha512,diffie-hellman-group16-sha512
DEBUG:asyncssh:[conn=20] Host key algs: ssh-ed25519,rsa-sha2-256,rsa-sha2-512
DEBUG:asyncssh:[conn=20] Client to server:
DEBUG:asyncssh:[conn=20] Encryption algs: [email protected],[email protected],aes256-ctr,aes192-ctr,aes128-ctr
DEBUG:asyncssh:[conn=20] MAC algs: [email protected],[email protected],hmac-sha2-512,hmac-sha2-256
DEBUG:asyncssh:[conn=20] Compression algs: none,zlib
DEBUG:asyncssh:[conn=20] Server to client:
DEBUG:asyncssh:[conn=20] Encryption algs: [email protected],[email protected],aes256-ctr,aes192-ctr,aes128-ctr
DEBUG:asyncssh:[conn=20] MAC algs: [email protected],[email protected],hmac-sha2-512,hmac-sha2-256
DEBUG:asyncssh:[conn=20] Compression algs: none,zlib
DEBUG:asyncssh:[conn=20] Beginning key exchange
DEBUG:asyncssh:[conn=20] Key exchange alg: curve25519-sha256
DEBUG:asyncssh.sftp:[conn=20, chan=0] Received 16384 data bytes
DEBUG:asyncssh.sftp:[conn=20, chan=0] Received 16384 data bytes
DEBUG:asyncssh.sftp:[conn=20, chan=0] Received 16384 data bytes
DEBUG:asyncssh.sftp:[conn=20, chan=0] Received 16384 data bytes
DEBUG:asyncssh.sftp:[conn=20, chan=0] Received 16384 data bytes
DEBUG:asyncssh.sftp:[conn=20, chan=0] Received 16384 data bytes
DEBUG:asyncssh.sftp:[conn=20, chan=0] Received 16384 data bytes
DEBUG:asyncssh.sftp:[conn=20, chan=0] Received 16384 data bytes
DEBUG:asyncssh.sftp:[conn=20, chan=0] Sending read for 16384 bytes at offset 1052311552 in handle 313033
DEBUG:asyncssh:[conn=20, chan=0] Sending 28 data bytes
DEBUG:asyncssh.sftp:[conn=20, chan=0] Sending read for 16384 bytes at offset 1052327936 in handle 313033
DEBUG:asyncssh:[conn=20, chan=0] Sending 28 data bytes
DEBUG:asyncssh.sftp:[conn=20, chan=0] Sending read for 16384 bytes at offset 1052344320 in handle 313033
DEBUG:asyncssh:[conn=20, chan=0] Sending 28 data bytes
DEBUG:asyncssh.sftp:[conn=20, chan=0] Sending read for 16384 bytes at offset 1052360704 in handle 313033
DEBUG:asyncssh:[conn=20, chan=0] Sending 28 data bytes
DEBUG:asyncssh.sftp:[conn=20, chan=0] Sending read for 16384 bytes at offset 1052377088 in handle 313033
DEBUG:asyncssh:[conn=20, chan=0] Sending 28 data bytes
DEBUG:asyncssh.sftp:[conn=20, chan=0] Sending read for 16384 bytes at offset 1052393472 in handle 313033
DEBUG:asyncssh:[conn=20, chan=0] Sending 28 data bytes
DEBUG:asyncssh.sftp:[conn=20, chan=0] Sending read for 16384 bytes at offset 1052409856 in handle 313033
DEBUG:asyncssh:[conn=20, chan=0] Sending 28 data bytes
DEBUG:asyncssh.sftp:[conn=20, chan=0] Sending read for 16384 bytes at offset 1052426240 in handle 313033
DEBUG:asyncssh:[conn=20, chan=0] Sending 28 data bytes
DEBUG:asyncssh:[conn=20] Sending keepalive request
DEBUG:asyncssh:[conn=20] Sending keepalive request
DEBUG:asyncssh:[conn=20] Sending keepalive request
INFO:asyncssh:[conn=20] Server not responding to keepalive
INFO:asyncssh:[conn=20, chan=0] Closing channel due to connection close
INFO:asyncssh:[conn=20, chan=0] Channel closed: Server not responding to keepalive
INFO:asyncssh.sftp:[conn=20, chan=0] SFTP client exited: Server not responding to keepalive
INFO:asyncssh:[conn=20, chan=0] Closing channel
DEBUG:asyncssh.sftp:[conn=20, chan=0] Sending close for handle 313033
INFO:asyncssh.sftp:[conn=20, chan=0] Starting SFTP get of XXXXXXXXXXXXXXXX to XXXXXXXXXXXXXXXX
DEBUG:asyncssh.sftp:[conn=20, chan=0] Sending lstat for XXXXXXXXXXXXXXXX
INFO:asyncssh:[conn=20] Closing connection
INFO:asyncssh:[conn=20] Sending disconnect: Disconnected by application (11)So far I've tried modifying both Any advice on where to go from here? |
|
So far, I'm unable to reproduce this here, using AsyncSSH as both client and server as well as an AsyncSSH client talking to an OpenSSH server. What client and server (and versions) are you using when you see the problem? Changing rekey_bytes on the client won't do much here, as almost all of the data is being sent by the server and rekey_bytes kicks in based on the number of bytes sent. So, if your server has this set to 1 GB, that'll be when you see the rekey happening. The fact that keepalive begins to fail at some point suggests that either something is hanging on the server side, or maybe that there's a problem with the network between the client and server after sending a large amount of data. You might try running AsyncSSH as both client and server and see if you still see the problem. You could also setting a lower value for rekey_bytes on the server side in this case. If you control the machine the SFTP server is running on, you could also change its config file to rekey sooner using OpenSSH as the server and see if the changes when the problem occurs. |
|
Thank you again for your input on this. It's perhaps worth mentioning that this connection just uses username + password for authentication. Could that be tripping up the rekey process? |
|
No - authentication isn't performed again during rekeying. Only the key exchange which happens prior to auth is repeated. Once complete, both sides switch over to new encryption keys, but the authentication information remains the same. |
|
Hey, so wanted to share an update here. The SFTP is hosted via the Move It Cloud service. We've been working with their support team to assess what's going on here. They just responded with the following note in case you are interested. Thanks again for your help! |
|
Thanks for the additional info. That is consistent with what I'm seeing in the trace. AsyncSSH is initiating a key exchange here by sending a new KEXINIT message, and it is getting back a KEXINIT in response. It then proceeds to start an ECDH key exchange (using curve25519-sha256), but that doesn't seem to complete. As a result, neither side seems to get to the point where NEWKEYS is sent and the new keys become active. It may not even be getting far enough to be able to generate those keys. Unfortunately, there's not much logging in the AsyncSSH key exchange code right now. Could you try setting the AsyncSSH debug level to 3 and post what you see after "Request key exchange"? That'll let us see what key exchange messages (if any) are sent/received. The expected result is for AsyncSSH to send a KEX_ECDH_INIT and then get back a KEX_ECDH_REPLY, after which both sides should be sending a NEWKEYS message. |
|
Sure thing @ronf! Here's what I'm seeing. Nothing is shown after the text below and the process simply hangs. |
|
Thanks! So, it looks like AsyncSSH is sending a proper MSG_KEX_ECDH_INIT after the KEXINIT messages, but the SSH server isn't sending the expected MSG_KEX_ECDH_REPLY in response, and so that's why AsyncSSH is "hanging". A proper exchange would look something like: The content of the KEX_ECDH_INIT is just the client's ephemeral public key bytes and that looks well-formed in your trace, so I don't know why the SSH server isn't replying to that. I wonder if maybe there's an issue with a fix for the Terrapin attack, where it thinks it is in the wrong state to do a key exchange. |
|
Thanks again! I sent your response on to the company and will let you know how they respond. |
|
Hey @ronf, Just heard back from the vendor on the latest. See below for the response and let me know if you have any additional questions. Thanks again!!
|
|
It shouldn't be too hard to make AsyncSSH not send MSG_IGNORE during later key exchanges. However, if you look at the description of strict-kex in the OpenSSH docs, it says:
Note the first sentence, where it says "During initial KEX" (emphasis mine). I don't think this requirement is meant to apply to rekeying, and AsyncSSH has no problem interoperating with OpenSSH even with it sending the MSG_IGNORE, suggesting that OpenSSH is not rejecting later key exchanges which have additional messages present. I was initially worried that there could be data in flight during rekeying that also might cause a problem. However, looking more closely at the original SSH RFCs, I see the following in RFC 4253 section 7.1:
So, in the original design, it looks like there's no concern about data in flight except for packets before the peer sends a KEXINIT. This means that the primary change with strict-kex was not allowing any messages of type 1-19 once the key exchange has started, which really comes down primarily to MSG_IGNORE and MSG_DEBUG. I still think it's wrong for the server here to enforce this on re-keying, but it gives me a bit more confidence that blocking these additional message types at both initial kex and rekeying might allow AsyncSSH to work with this server. |
|
Here's a potential fix you can test: diff --git a/asyncssh/connection.py b/asyncssh/connection.py
index 2db356b..3ea2af4 100644
--- a/asyncssh/connection.py
+++ b/asyncssh/connection.py
@@ -1742,7 +1742,7 @@ class SSHConnection(SSHPacketHandler, asyncio.Protocol):
self._kexinit_sent = True
if (((pkttype in {MSG_SERVICE_REQUEST, MSG_SERVICE_ACCEPT} or
- pkttype > MSG_KEX_LAST) and not self._kex_complete) or
+ pkttype > MSG_KEX_LAST) and self._kexinit_sent) or
(pkttype == MSG_USERAUTH_BANNER and
not (self._auth_in_progress or self._auth_complete)) or
(pkttype > MSG_USERAUTH_LAST and not self._auth_complete)):
@@ -1751,7 +1751,7 @@ class SSHConnection(SSHPacketHandler, asyncio.Protocol):
# If we're encrypting and we have no data outstanding, insert an
# ignore packet into the stream
- if self._send_encryption and pkttype not in (MSG_IGNORE, MSG_EXT_INFO):
+ if self._send_encryption and pkttype > MSG_KEX_LAST:
self.send_packet(MSG_IGNORE, String(b''))
orig_payload = Byte(pkttype) + b''.join(args)
@@ -1934,6 +1934,7 @@ class SSHConnection(SSHPacketHandler, asyncio.Protocol):
self._mac_alg_sc, mac_key_sc, etm_sc)
self.send_packet(MSG_NEWKEYS)
+ self._kexinit_sent = False
self._extensions_to_send[b'global-requests-ok'] = b''
@@ -2368,10 +2369,9 @@ class SSHConnection(SSHPacketHandler, asyncio.Protocol):
'KEXINIT was not the first packet')
- if self._kexinit_sent:
- self._kexinit_sent = False
- else:
+ if not self._kexinit_sent:
self._send_kexinit()
+ self._kexinit_sent = True
if self._gss:
self._gss.reset()It will also require some minor tweaks in the unit testing, but you shouldn't need those to give this a try. This change avoids sending MSG_IGNORE for any of the messages below KEX_LAST rather than only singling out specific messages where sending it has been a problem in the past. In addition, it makes sure to defer sending any additional data messages during the key exchange, whether it is the initial kex or a rekeying. Technically, there is also an issue here if send_debug() is called on a connection during a key exchange, so I may need to also handle that case, but first I want to see if the above fixes the main issue. |
|
Appears that did the trick! Transfers completed and rekey did not trip up the process as it had before. Even when I use the "rekey_seconds" parameter to prompt an early rekey, the process continues just fine. Let me know if there's anything else you'd like me to check on my end. Thanks again! |
|
Could you try one more version of this? After looking at it a second time, I came up with a simpler patch: diff --git a/asyncssh/connection.py b/asyncssh/connection.py
index 2db356b..6656255 100644
--- a/asyncssh/connection.py
+++ b/asyncssh/connection.py
@@ -1741,7 +1741,7 @@ class SSHConnection(SSHPacketHandler, asyncio.Protocol):
self._send_kexinit()
self._kexinit_sent = True
- if (((pkttype in {MSG_SERVICE_REQUEST, MSG_SERVICE_ACCEPT} or
+ if (((pkttype in {MSG_DEBUG, MSG_SERVICE_REQUEST, MSG_SERVICE_ACCEPT} or
pkttype > MSG_KEX_LAST) and not self._kex_complete) or
(pkttype == MSG_USERAUTH_BANNER and
not (self._auth_in_progress or self._auth_complete)) or
@@ -1751,7 +1751,7 @@ class SSHConnection(SSHPacketHandler, asyncio.Protocol):
# If we're encrypting and we have no data outstanding, insert an
# ignore packet into the stream
- if self._send_encryption and pkttype not in (MSG_IGNORE, MSG_EXT_INFO):
+ if self._send_encryption and pkttype > MSG_KEX_LAST:
self.send_packet(MSG_IGNORE, String(b''))
orig_payload = Byte(pkttype) + b''.join(args)Also, would you mind passing on my previous comments about initial kex vs. rekeying above to the SFTP library vendor? I'm happy to leave my change in place, but I do consider it a workaround for a problem in the library given the wording in the OpenSSH strict-kex specification. |
|
Hey @ronf, That works too!! I also passed along your feedback to our vendor and will let you know how they respond. Thanks again! |
|
Sounds good - thanks very much! This change is now available as commit b88eed6 in the "develop" branch and will be included in the next release. Thanks for your help tracking this down, and for testing the potential fixes! |
Trying to solve an issue where running .get() on a large file (4GB+) will work at first but appears to eventually exhaust the system's RAM and results in the download freezing.
When using .get(), does asyncssh write data to the destination file as it arrives or does everything need to be collected into memory before it can actually be written to a file?
If it's the latter, is there a way to incrementally download a file from an SFTP and write chunks to the destination file as it goes, allowing the system to then clear some memory space? Or is there another way to recommended approach for instances where file sizes are larger than memory?
The text was updated successfully, but these errors were encountered: