theophilusx / ssh2-sftp-client

a client for SSH2 SFTP
Apache License 2.0
819 stars 200 forks source link

Put files truncating at 100kb when not reading from file #531

Closed tristansokol closed 6 months ago

tristansokol commented 7 months ago

Hi! I'm encountering a weird bug and am hoping for some direction on where to go.

Basically I have files that are being truncated after the first 102,000 bytes. Smaller files work fine, but larger ones report success but are clearly truncated. "manually" connecting with $ sftp from the same machine works fine which from what I understand eliminates the issues of https://github.com/theophilusx/ssh2-sftp-client/issues/342

The code is very simple:

  const sftp = new SFTPClient();
  await sftp.connect({
    host: ...,
    port: '22',
    username: ...,
    password: ...
  });
  console.log(data.length) // just over a million bytes
  console.log(await sftp.put(Buffer.from(data), `/D:/Shares/${name}.pdf`));
  await sftp.end();

and the logs:

CLIENT[sftp]: connect: Debugging turned on
CLIENT[sftp]: ssh2-sftp-client Version: 10.0.3  {
 "node": "20.3.1",
 "acorn": "8.8.2",
 "ada": "2.5.0",
 "ares": "1.19.1",
 "base64": "0.5.0",
 "brotli": "1.0.9",
 "cjs_module_lexer": "1.2.2",
 "cldr": "43.0",
 "icu": "73.1",
 "llhttp": "8.1.1",
 "modules": "115",
 "napi": "9",
 "nghttp2": "1.53.0",
 "nghttp3": "0.7.0",
 "ngtcp2": "0.8.1",
 "openssl": "3.0.9+quic",
 "simdutf": "3.2.12",
 "tz": "2023c",
 "undici": "5.22.1",
 "unicode": "15.0",
 "uv": "1.45.0",
 "uvwasi": "0.0.18",
 "v8": "11.3.244.8-node.9",
 "zlib": "1.2.13.1-motley"
}
CLIENT[sftp]: connect: Connect attempt 1
Custom crypto binding not available
Local ident: 'SSH-2.0-ssh2js1.15.0'
Client: Trying sftp.... on port 22 ...
Socket connected
Remote ident: 'SSH-2.0-OpenSSH_for_Windows_8.1'
Outbound: Sending KEXINIT
Inbound: Handshake in progress
Handshake: (local) KEX method: curve25519-sha256@libssh.org,curve25519-sha256,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,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,ext-info-c,kex-strict-c-v00@openssh.com
Handshake: (remote) KEX method: curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1
Handshake: KEX algorithm: curve25519-sha256@libssh.org
Handshake: (local) Host key format: ssh-ed25519,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,rsa-sha2-512,rsa-sha2-256,ssh-rsa
Handshake: (remote) Host key format: rsa-sha2-512,rsa-sha2-256,ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519
Handshake: Host key format: ssh-ed25519
Handshake: (local) C->S cipher: aes128-gcm@openssh.com,aes256-gcm@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,chacha20-poly1305@openssh.com
Handshake: (remote) C->S cipher: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com
Handshake: C->S Cipher: aes128-gcm@openssh.com
Handshake: (local) S->C cipher: aes128-gcm@openssh.com,aes256-gcm@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,chacha20-poly1305@openssh.com
Handshake: (remote) S->C cipher: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com
Handshake: S->C cipher: aes128-gcm@openssh.com
Handshake: (local) C->S MAC: hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
Handshake: (remote) C->S MAC: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
Handshake: C->S MAC: <implicit>
Handshake: (local) S->C MAC: hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
Handshake: (remote) S->C MAC: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
Handshake: S->C MAC: <implicit>
Handshake: (local) C->S compression: none,zlib@openssh.com,zlib
Handshake: (remote) C->S compression: none,zlib@openssh.com
Handshake: C->S compression: none
Handshake: (local) S->C compression: none,zlib@openssh.com,zlib
Handshake: (remote) S->C compression: none,zlib@openssh.com
Handshake: S->C compression: none
Outbound: Sending KEXECDH_INIT
Received DH Reply
Host accepted by default (no verification)
Host accepted (verified)
Outbound: Sending NEWKEYS
Inbound: NEWKEYS
Verifying signature ...
Verified signature
Handshake completed
Outbound: Sending SERVICE_REQUEST (ssh-userauth)
Inbound: Received EXT_INFO
Inbound: Received SERVICE_ACCEPT (ssh-userauth)
Outbound: Sending USERAUTH_REQUEST (none)
Inbound: Received USERAUTH_FAILURE (publickey,password,keyboard-interactive)
Client: none auth failed
Outbound: Sending USERAUTH_REQUEST (password)
Inbound: Received USERAUTH_SUCCESS
CLIENT[sftp]: getConnection ready listener: got connection - promise resolved
Outbound: Sending CHANNEL_OPEN (r:0, session)
Inbound: GLOBAL_REQUEST (hostkeys-00@openssh.com)
Inbound: CHANNEL_OPEN_CONFIRMATION (r:0, s:0)
Outbound: Sending CHANNEL_REQUEST (r:0, subsystem: sftp)
Inbound: CHANNEL_WINDOW_ADJUST (r:0, 2097152)
Inbound: CHANNEL_SUCCESS (r:0)
Outbound: Sending CHANNEL_DATA (r:0, 9)
Inbound: CHANNEL_DATA (r:0, 183)
SFTP: Inbound: Received VERSION (v3, exts:posix-rename@openssh.com,statvfs@openssh.com,fstatvfs@openssh.com,hardlink@openssh.com,fsync@openssh.com,lsetstat@openssh.com)
Outbound: Sending CHANNEL_DATA (r:0, 86)
SFTP: Outbound: Buffered OPEN
CLIENT[sftp]: put source is a buffer
Inbound: CHANNEL_DATA (r:0, 17)
SFTP: Inbound: Received HANDLE (id:0)
Outbound: Sending CHANNEL_DATA (r:0, 25)
SFTP: Outbound: Buffered FSETSTAT
Inbound: CHANNEL_DATA (r:0, 28)
SFTP: Inbound: Received STATUS (id:1, 0, "Success")
Outbound: Sending CHANNEL_DATA (r:0, 32768)
Outbound: Sending CHANNEL_DATA (r:0, 32768)
Outbound: Sending CHANNEL_DATA (r:0, 32768)
Outbound: Sending CHANNEL_DATA (r:0, 32768)
Outbound: Sending CHANNEL_DATA (r:0, 32768)
Outbound: Sending CHANNEL_DATA (r:0, 32768)
Outbound: Sending CHANNEL_DATA (r:0, 32768)
Outbound: Sending CHANNEL_DATA (r:0, 30749)
SFTP: Outbound: Sent WRITE (id:2)
Inbound: CHANNEL_WINDOW_ADJUST (r:0, 98424)
Inbound: CHANNEL_WINDOW_ADJUST (r:0, 131072)
Inbound: CHANNEL_DATA (r:0, 28)
SFTP: Inbound: Received STATUS (id:2, 4, "Failure")
Outbound: Sending CHANNEL_DATA (r:0, 17)
SFTP: Outbound: Buffered CLOSE
Inbound: CHANNEL_DATA (r:0, 28)
SFTP: Inbound: Received STATUS (id:3, 0, "Success")
Uploaded data stream to /D:/test.pdf
Outbound: Sending DISCONNECT (11)
Socket error: read ECONNRESET
CLIENT[sftp]: end errorListener - ignoring handled error
CLIENT[sftp]: Global error event: Ignoring expected and handled event
Socket closed
CLIENT[sftp]: end: Connection closed
CLIENT[sftp]: end closeListener - handled close event
CLIENT[sftp]: Global close event: Ignoring expected and handled event

I the log message Uploaded data stream to /D:/Shares/0097643.pdf which seems like everything is correct. what does the SFTP: Inbound: Received STATUS (id:2, 4, "Failure") mean? I initially suspected there being some kind of FPT quota or something, but again, I am able to transfer larger files just fine from the same machine with other SFTP tools.

Any advice as to where to dig in more? Could this be a bug?

tristansokol commented 7 months ago

Additionally, wrapping my filename in a createReadStream seems to work just fine, so I am kind of leaning towards there being a bug, or at least I'm using the filename or buffer methods incorrectly.

tristansokol commented 7 months ago

Alright instead of more comments I'll just update this one with my findings

  const sftp = new SFTPClient();
  await sftp.connect({
    host:
    port: '22',
    username: 
    password: 
  });
`console.log(pdf.length, pdf.byteLength, Buffer.isBuffer(pdf)); //1882193 1882193 true`

  await sftp.put(pdf, `${name}.pdf`);
  console.log(await sftp.stat(`${name}.pdf`));
  await sftp.end();
Technique Result
.put(pdf,.. size: 102400,
writeFileSync('./test.pdf', pdf); await put('./test.pdf',..); size: 1882193,
put(createReadStream('./test.pdf'),... size: 1882193,
put(Readable.from(pdf),... size: 102400,
put(readFileSync('./test.pdf'),...//reading the file logs 1882193 bytes size: 102400,
theophilusx commented 7 months ago

If this is a bug, you have neglected to provide any where near sufficient details for me to reproduce it. Being able to reproduce the issue is the first step.

You need to supply

Also, if you can provide a complete minimal example script which reproduces the issue, that would help a lot.

When this type of issue has been reported by others in the past. in every case the issue was due to the client script calling end() before the put/get or fastPut/fastGet had completed or the data source being truncated before it was ppassed to the client (I suspect this is your issue based on your finding that wrapping the buffer in a read stream makes it work). Therefore, first steps are to eliminate the simpler possibilities.

First step, remove the call to end() and see if that makes any difference. If the data is transferred with no problem, then we know the issue is because end() is being called before put() has completed and we can then focus on why that is happening.

If removing end() makes no difference, then we need to focus on the data source. I would do the following

  1. Create a test file by writing your buffer to a local file. Open a local write stream and pipe the buffer into the stream use the stream pipe() method (this mirrors how the client works internally). Verify the integrity and size of the crated file.

  2. Use the file created above and call put() using the filename. If this works, then we know it is some issue with the buffer source.

  3. As another test, open a read stream on the test file created in 1 and pass that in as the source to put(). If that also works, then we have even more confirmation the problem is with the buffer being passed in.

If we get to this point, you need to then generate a test script which includes the buffer creation code and supply that so that I can test it and try to reproduce the issue. If I cannot reproduce the issue, I cannot resolve any possible issue.

Note that if you are using windows, which it appears you are, my ability to help is very limited. I don't run windows and I no longer have access to a windows environment for testing. Last time I did have access and was able to test on windows, all worked fine. However, that was a while ago, so who knows.

Tristan Sokol @.***> writes:

Alright instead of more comments I'll just update this one with my findings

const sftp = new SFTPClient(); await sftp.connect({ host: port: '22', username: password: }); console.log(pdf.length, pdf.byteLength, Buffer.isBuffer(pdf)); //1882193 1882193 true

await sftp.put(pdf, ${name}.pdf); console.log(await sftp.stat(${name}.pdf)); await sftp.end();

Technique Result
.put(pdf,.. size: 102400,
writeFileSync('./test.pdf', pdf); await put('./test.pdf',..); size: 1882193,
put(createReadStream('./test.pdf'),... size: 1882193,
put(Readable.from(pdf),... size: 102400,
put(readFileSync('./test.pdf'),...//reading the file logs 1882193 bytes size: 102400,

— Reply to this email directly, view it on GitHub, or unsubscribe. You are receiving this because you are subscribed to this thread.

tristansokol commented 7 months ago

Thank you! I had actually caught that I forgot those important details and made a fast follow-on edit, but I know they don't update the emails so I'll include them here as well

I created the following script using the (hopefully innocent) 1mb file I randomly found googling: https://gist.githubusercontent.com/khaykov/a6105154becce4c0530da38e723c2330/raw/41ab415ac41c93a198f7da5b47d604956157c5c3/gistfile1.txt

import SFTPClient from 'ssh2-sftp-client';
const file = readFileSync('./gistfile1.txt');
console.log(file.length, Buffer.isBuffer(file));
const sftp = new SFTPClient();
await sftp.connect({
  host: '...',
  port: '22',
  username: ...
  password: ...,
  // debug: (msg) => {
  //   console.error(msg);
  // },
});
await sftp.put(file, `/D:/test.pdf`);
console.log(await sftp.stat(`/D:/test.pdf`));
await sftp.end();

which exhibits the issues I describe:

1048575 true //file is a 1mb buffer
{
  mode: 33159,
  uid: 0,
  gid: 0,
  size: 102400, //only part of it gets uploaded
  accessTime: 1713484422000,
  modifyTime: 1713484422000,
  isDirectory: false,
  isFile: true,
  isBlockDevice: false,
  isCharacterDevice: false,
  isSymbolicLink: false,
  isFIFO: false,
  isSocket: false
}

I tried your removing end() but it made no difference (aside from causing the script to hang)

  1. Create a test file by writing your buffer to a local file. Open a local write stream and pipe the buffer into the stream use the stream pipe() method (this mirrors how the client works internally). Verify the integrity and size of the crated file. Since I'm using a local file to start now I think this should be handled, but let me know if I misunderstood.

  2. Use the file created above and call put() using the filename. If this works, then we know it is some issue with the buffer source.

const sftp = new SFTPClient();
await sftp.connect({
  host: '...',
  port: '22',
  username: ...,
  password: ...,
  // debug: (msg) => {
  //   console.error(msg);
  // },
});
await sftp.put('./gistfile1.txt', '/D:/test.pdf');
console.log(await sftp.stat('/D:/test.pdf'));
await sftp.end();
{
  mode: 33159,
  uid: 0,
  gid: 0,
  size: 1048575, //full file size
  accessTime: 1713487711000,
  modifyTime: 1713487711000,
  isDirectory: false,
  isFile: true,
  isBlockDevice: false,
  isCharacterDevice: false,
  isSymbolicLink: false,
  isFIFO: false,
  isSocket: false
}

This works as intended, but I'm not sure if I would agree that this indicates an issue with the buffer source. (the buffer source is readFileSync, which by all means available seems to be reading the file as a buffer correctly. )

  1. As another test, open a read stream on the test file created in 1 and pass that in as the source to put(). If that also works, then we have even more confirmation the problem is with the buffer being passed in.
    const sftp = new SFTPClient();
    await sftp.connect({
    host: '...',
    port: '22',
    username: ...,
    password: ...,
    // debug: (msg) => {
    //   console.error(msg);
    // },
    });
    await sftp.put(createReadStream('./gistfile1.txt'), '/D:/test.pdf');
    console.log(await sftp.stat('/D:/test.pdf'));
    await sftp.end();

    This works just fine as well.

I am testing locally with WSL (Ubuntu 22.04.2 LTS) but have confirmed this behavior on linux instances in GCP.

Let me know if this triggers any other thoughts!

theophilusx commented 7 months ago

I've had a closer look at your issue. Unfortunately, I could not reproduce using your data (and my own data) using either my own script or your (slightly modified) script. This was using node v20.12.2 on Linux (Fedora 39) and connecting to a remote SFTP server running on a Fedora 39 server running openSSH OpenSSH_9.3p1, OpenSSL 3.1.1 30 May 2023

Something I did recall which may be of relevance. Some time back, there was another user having problems with truncated data. After investigation, it turned out to be due to a network issue associated with WSL. It was related to MTU size. I recall it because back in the 'old days' i.e. mid 1990s, it was common to have to set a smaller mtu size on windows 'winsock' because of problems with default standard mtu size (I'm sure if you google it you will find something). I have also heard of similar issues when using docker on windows.

To, my suggestion would be to try testing your scripts outside a WSL environment and see if you get a similar issue. You could also try reducing the size of your MTU. I did a quick google on this and saw there were lots of articles about people having to reset MTU when using WSL, especially wrt large data transfers. Sorry, but not sure what a good size would be. You probably need to experiment.

For reference, below is the modified version of your script I used. The modifications are cosmetic and I don't think changed any functionality. Note that there are other example scripts in the example directory of the ssh2-sftp-client repository, including some using buffers for input to put().

BTW re-iterate, unless you have to use buffers, your far better off using either a readStream (my preferred method) or passing a file path. Buffers are really only useful in a very limited set of use cases and most of these cases can now be dealt with using the far more efficient stream model.

import path from 'node:path'; import fs from 'node:fs'; import SFTPClient from 'ssh2-sftp-client'; import 'dotenv/config';

const file = fs.readFileSync('./gistfile1.txt'); console.log(buffer size: ${file.length} Is a buffer: ${Buffer.isBuffer(file)});

const sftp = new SFTPClient(); await sftp.connect({ host: process.env.SFTP_SERVER, username: process.env.SFTP_USER, password: process.env.SFTP_PASSWORD, port: process.env.SFTP_PORT || 22, // debug: (msg) => { // console.error(msg); // }, });

const remotePath = './ts-data.txt'; await sftp.put(file, remotePath); console.log(await sftp.stat(remotePath)); await sftp.end();

tristansokol commented 6 months ago

Thanks again for your help.

to close the loop here, I was able to get the server upgraded from OpenSSH 8.1 > 9.5 and that seems to have fixed the issue.