sftp.put hangs after creating the file

[p-j]

Hi,

I'm trying to do a simple upload of a small CSV file I'm generating on the fly.
Here is the relevant portion of the code

const data = Buffer.from(csv)
const sftp = new Client()
try {
  await sftp.connect({
    host: HOST,
    username: USERNAME,
    password: PASSWORD,
    port: PORT,
    debug: console.info
  })
  await sftp.put(data, '/path/to/file.csv')
} catch (e) {
  console.error(e)
} finally {
  await sftp.end()
}

When doing so, most of the time the upload will hang, with logs showing:

CLIENT[sftp]: exists -> /path/to/file.csv
CLIENT[sftp]: stat -> /path/to/file.csv
DEBUG[SFTP]: Outgoing: Writing STAT
DEBUG: Outgoing: Writing CHANNEL_DATA (0)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: Decrypting
DEBUG: Parser: pktLen:60,padLen:9,remainLen:48
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: Decrypting
DEBUG: Parser: HMAC size:32
DEBUG: Parser: IN_PACKETDATAVERIFY
DEBUG: Parser: Verifying MAC
DEBUG: Parser: IN_PACKETDATAVERIFY (Valid HMAC)
DEBUG: Parser: IN_PACKETDATAAFTER, packet: CHANNEL_DATA (0)
DEBUG[SFTP]: Parser: Response: ATTRS
CLIENT[sftp]: stats <-  {
 "mode": 33206,
 "permissions": 33206,
 "uid": 1026,
 "gid": 100,
 "size": 0,
 "atime": 1595344292,
 "mtime": 1595347428
}
CLIENT[sftp]: Removing listener from error
CLIENT[sftp]: Removing listener from close
DEBUG: Parser: IN_PACKETBEFORE (expecting 16)
CLIENT[sftp]: exists <-  {
 "mode": 33206,
 "uid": 1026,
 "gid": 100,
 "size": 0,
 "accessTime": 1595344292000,
 "modifyTime": 1595347428000,
 "isDirectory": false,
 "isFile": true,
 "isBlockDevice": false,
 "isCharacterDevice": false,
 "isSymbolicLink": false,
 "isFIFO": false,
 "isSocket": false
}
CLIENT[sftp]: put remote path info  {
 "path": "/path/to/file.csv",
 "type": "-",
 "valid": true
}
CLIENT[sftp]: put -> /path/to/file.csv
DEBUG[SFTP]: Outgoing: Writing OPEN
DEBUG: Outgoing: Writing CHANNEL_DATA (0)
CLIENT[sftp]: put source is a buffer
DEBUG: Parser: IN_PACKET
DEBUG: Parser: Decrypting
DEBUG: Parser: pktLen:44,padLen:17,remainLen:32
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: Decrypting
DEBUG: Parser: HMAC size:32
DEBUG: Parser: IN_PACKETDATAVERIFY
DEBUG: Parser: Verifying MAC
DEBUG: Parser: IN_PACKETDATAVERIFY (Valid HMAC)
DEBUG: Parser: IN_PACKETDATAAFTER, packet: CHANNEL_DATA (0)
DEBUG[SFTP]: Parser: Response: HANDLE
DEBUG[SFTP]: Outgoing: Writing FSETSTAT
DEBUG: Outgoing: Writing CHANNEL_DATA (0)
DEBUG: Parser: IN_PACKETBEFORE (expecting 16)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: Decrypting
DEBUG: Parser: pktLen:44,padLen:6,remainLen:32
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: Decrypting
DEBUG: Parser: HMAC size:32
DEBUG: Parser: IN_PACKETDATAVERIFY
DEBUG: Parser: Verifying MAC
DEBUG: Parser: IN_PACKETDATAVERIFY (Valid HMAC)
DEBUG: Parser: IN_PACKETDATAAFTER, packet: CHANNEL_DATA (0)
DEBUG[SFTP]: Parser: Response: STATUS
DEBUG[SFTP]: Outgoing: Writing WRITE
DEBUG: Outgoing: Writing CHANNEL_DATA (0)
DEBUG: Outgoing: Writing CHANNEL_DATA (0)
DEBUG: Outgoing: Writing CHANNEL_DATA (0)
DEBUG: Outgoing: Writing CHANNEL_DATA (0)
DEBUG: Parser: IN_PACKETBEFORE (expecting 16)
DEBUG: Outgoing: Writing CHANNEL_DATA (0)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: Decrypting
DEBUG: Parser: pktLen:28,padLen:18,remainLen:16
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: Decrypting
DEBUG: Parser: HMAC size:32
DEBUG: Parser: IN_PACKETDATAVERIFY
DEBUG: Parser: Verifying MAC
DEBUG: Parser: IN_PACKETDATAVERIFY (Valid HMAC)
DEBUG: Parser: IN_PACKETDATAAFTER, packet: CHANNEL_WINDOW_ADJUST (0, 98482)
DEBUG: Parser: IN_PACKETBEFORE (expecting 16)

and it will stay like so forever

Sometime, completely at random, it will go through and in thise case the logs will be like that:

CLIENT[sftp]: exists -> /path/to/file.csv
CLIENT[sftp]: stat -> /path/to/file.csv
DEBUG[SFTP]: Outgoing: Writing STAT
DEBUG: Outgoing: Writing CHANNEL_DATA (0)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: Decrypting
DEBUG: Parser: pktLen:60,padLen:9,remainLen:48
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: Decrypting
DEBUG: Parser: HMAC size:32
DEBUG: Parser: IN_PACKETDATAVERIFY
DEBUG: Parser: Verifying MAC
DEBUG: Parser: IN_PACKETDATAVERIFY (Valid HMAC)
DEBUG: Parser: IN_PACKETDATAAFTER, packet: CHANNEL_DATA (0)
DEBUG[SFTP]: Parser: Response: ATTRS
CLIENT[sftp]: stats <-  {
 "mode": 33206,
 "permissions": 33206,
 "uid": 1026,
 "gid": 100,
 "size": 0,
 "atime": 1595344292,
 "mtime": 1595347522
}
CLIENT[sftp]: Removing listener from error
CLIENT[sftp]: Removing listener from close
DEBUG: Parser: IN_PACKETBEFORE (expecting 16)
CLIENT[sftp]: exists <-  {
 "mode": 33206,
 "uid": 1026,
 "gid": 100,
 "size": 0,
 "accessTime": 1595344292000,
 "modifyTime": 1595347522000,
 "isDirectory": false,
 "isFile": true,
 "isBlockDevice": false,
 "isCharacterDevice": false,
 "isSymbolicLink": false,
 "isFIFO": false,
 "isSocket": false
}
CLIENT[sftp]: put remote path info  {
 "path": "/path/to/file.csv",
 "type": "-",
 "valid": true
}
CLIENT[sftp]: put -> /path/to/file.csv
DEBUG[SFTP]: Outgoing: Writing OPEN
DEBUG: Outgoing: Writing CHANNEL_DATA (0)
CLIENT[sftp]: put source is a buffer
DEBUG: Parser: IN_PACKET
DEBUG: Parser: Decrypting
DEBUG: Parser: pktLen:44,padLen:17,remainLen:32
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: Decrypting
DEBUG: Parser: HMAC size:32
DEBUG: Parser: IN_PACKETDATAVERIFY
DEBUG: Parser: Verifying MAC
DEBUG: Parser: IN_PACKETDATAVERIFY (Valid HMAC)
DEBUG: Parser: IN_PACKETDATAAFTER, packet: CHANNEL_DATA (0)
DEBUG[SFTP]: Parser: Response: HANDLE
DEBUG[SFTP]: Outgoing: Writing FSETSTAT
DEBUG: Outgoing: Writing CHANNEL_DATA (0)
DEBUG: Parser: IN_PACKETBEFORE (expecting 16)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: Decrypting
DEBUG: Parser: pktLen:44,padLen:6,remainLen:32
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: Decrypting
DEBUG: Parser: HMAC size:32
DEBUG: Parser: IN_PACKETDATAVERIFY
DEBUG: Parser: Verifying MAC
DEBUG: Parser: IN_PACKETDATAVERIFY (Valid HMAC)
DEBUG: Parser: IN_PACKETDATAAFTER, packet: CHANNEL_DATA (0)
DEBUG[SFTP]: Parser: Response: STATUS
DEBUG[SFTP]: Outgoing: Writing WRITE
DEBUG: Outgoing: Writing CHANNEL_DATA (0)
DEBUG: Outgoing: Writing CHANNEL_DATA (0)
DEBUG: Outgoing: Writing CHANNEL_DATA (0)
DEBUG: Outgoing: Writing CHANNEL_DATA (0)
DEBUG: Parser: IN_PACKETBEFORE (expecting 16)
DEBUG: Outgoing: Writing CHANNEL_DATA (0)
DEBUG: Outgoing: Writing CHANNEL_DATA (0)
DEBUG: Outgoing: Writing CHANNEL_DATA (0)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: Decrypting
DEBUG: Parser: pktLen:28,padLen:18,remainLen:16
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: Decrypting
DEBUG: Parser: HMAC size:32
DEBUG: Parser: IN_PACKETDATAVERIFY
DEBUG: Parser: Verifying MAC
DEBUG: Parser: IN_PACKETDATAVERIFY (Valid HMAC)
DEBUG: Parser: IN_PACKETDATAAFTER, packet: CHANNEL_WINDOW_ADJUST (0, 98482)
DEBUG: Parser: IN_PACKETBEFORE (expecting 16)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: Decrypting
DEBUG: Parser: pktLen:28,padLen:18,remainLen:16
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: Decrypting
DEBUG: Parser: HMAC size:32
DEBUG: Parser: IN_PACKETDATAVERIFY
DEBUG: Parser: Verifying MAC
DEBUG: Parser: IN_PACKETDATAVERIFY (Valid HMAC)
DEBUG: Parser: IN_PACKETDATAAFTER, packet: CHANNEL_WINDOW_ADJUST (0, 102171)
DEBUG: Parser: IN_PACKETBEFORE (expecting 16)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: Decrypting
DEBUG: Parser: pktLen:44,padLen:6,remainLen:32
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: Decrypting
DEBUG: Parser: HMAC size:32
DEBUG: Parser: IN_PACKETDATAVERIFY
DEBUG: Parser: Verifying MAC
DEBUG: Parser: IN_PACKETDATAVERIFY (Valid HMAC)
DEBUG: Parser: IN_PACKETDATAAFTER, packet: CHANNEL_DATA (0)
DEBUG[SFTP]: Parser: Response: STATUS
DEBUG: Parser: IN_PACKETBEFORE (expecting 16)
DEBUG[SFTP]: Outgoing: Writing CLOSE
DEBUG: Outgoing: Writing CHANNEL_DATA (0)
CLIENT[sftp]: Removing listener from error
CLIENT[sftp]: Removing listener from close
DEBUG: Outgoing: Writing DISCONNECT (BY_APPLICATION)
CLIENT[sftp]: Removing listener from error

I'm currently running Node v14.4.0, so I'm wondering if this could be linked to mscdex/ssh2-streams#156 ?

You mention in this issue that using a concurrency of 1 it's working all the time, and my understanding was that client.put is running in the same configuration which is why I'm opening this issue here as I'm not sure it's the same.

Do you have any idea what I could do to ensure a more consistent result while running Node >= v14.1.0 ?

Thanks

[theophilusx]

I don't think it is the same issue as the one identified with fastPut/fastGet, but cannot guarantee that for certain. Can you downgrade to latest v12 of node and see if the issue persists? If it doesn't, then either it is the same issue or something similar peculiar to v14. Until the identified issues with fastPut/fastGet are resolved when using v14 of node, I would avoid using it. The node v14 change log states there have been some fundamental changes to some of the stream APIs and I am not confident there are not issues which still need to be resolved in that version.

[p-j]

Thanks for your response @theophilusx
I plan on checking this by the end of the week. I'll be posting some feedback then.

[p-j]

Hi @theophilusx
I've tested both Node v13.14 and Node v14.5 today.
Both works fine with very small files.
Moving to larger files (in my case 842Ko CSV File)
Node v13.14 continues to produce good result but Node v14.5 hangs after creating the file. I end up with an empty file on the sftp server.

I'll be conducting more tests tomorrow with Node 14.0 & upward to see if the issue is indeed introduced by v14.1 as reported in the other issue.

[theophilusx]

That is beginning to sound like it might be related to the same issue as for fastPut/fastGet. You might find some of the scripts in the example directory of the git repo useful. These scripts only use the underlying ssh2 and ssh2-streams libraries. If you are able to reproduce the issue just using ssh2 and ssh2-streams, then it means the issue is in those upstream modules and needs to be addressed there.

[p-j]

I can confirm this is working on v14.0.0 and not on v14.1.0 with a big enough file.

[p-j]

I've also been able to reproduce the behavior with both

• example/buffer-put
• example/buffer-test

On Node >= 14.1 node buffer-test.js 1000 /home/test will hang most of the time
On Node <= 14.0 node buffer-test.js 1000 /home/test will go through most of the time

[theophilusx]

OK, thanks. That looks like it is most likely related to the previously identified issue with the upstream dependency on ssh2/ssh2-streams. What we need now is a minimal test case which only uses those dependencies (no ssh2-sftp-client) and then log an issue with the upstream developer. I should be able to find time to put together a test script before the end of the week. However, if I do, it would be great if you can log the issue as I'm hoping if another issue is logged by someone else, it might gain some more traction (does not seem to have been much action on my original issue). I'll let you know when I've done the test script and uploaded it.

[theophilusx]

I have added the script tools/lowlevel-put.js which does a 'put' of a file to a remote server just using ssh2. I was unable to reproduce any errors with any node version using this script. It uses a stream to read the source file and pipe to send it to a remote stream (how ssh2-sft-client does it). The script expects to command line arguments, a path to a local source file and the remote path to upload the file to (including filename). I tested with small and large files (e.g. 500Mb). I also tested on two different servers with different sftp server configurations. I'll create another script which uses a buffer rather than a read stream as the source to eliminate that as the problem.

[theophilusx]

OK, added the script tools/lowlevel-buffer-put.js, which generates a buffer of requested size and puts it up to the remote server. This time, I was able to reproduce the issue using just the ssh2/ssh2-streams libs. The issue is intermittent - so running the script with the same parameters can work a couple of times and then fails. (hangs with 0 byte file on server). The script expects 2 params - size (number of kbytes) and destination file path. Will see if I can dig further and will try different ways of handling the buffer to see if that makes a difference. Seems the problem is specific to using a buffer for input. Could not reproduce it using a stream.

[p-j]

Hi @theophilusx
I've made a small change to your script here: master...p-j:master
This highlights the following, in v13.12.0 I get the following:

jeremie@xps ➜  tools git:(master) ✗ node lowlevel-buffer-put.js 1000 /home/test/$(date +"%Y-%m-%d_%H-%M-%S").bin
Uploading buffer of 1024000 bytes to /home/test/2020-08-04_09-46-02.bin
write stream pipe
read stream resume
read stream data
read stream pause
read stream end
File successfully uploaded to /home/test/2020-08-04_09-46-02.bin
write stream unpipe

while running v14.7.0

jeremie@xps ➜  tools git:(master) ✗ nvm use v14.7   
Now using node v14.7.0 (npm v6.14.7)
jeremie@xps ➜  tools git:(master) ✗ node lowlevel-buffer-put.js 1000 /home/test/$(date +"%Y-%m-%d_%H-%M-%S").bin
Uploading buffer of 1024000 bytes to /home/test/2020-08-04_09-46-38.bin
write stream pipe
read stream resume
read stream data
read stream pause
read stream end
read stream close
^C

The difference being the close event being emitted in the v14.7 and not in the v13.12

[theophilusx]

Good work. I was going to do essentially the same and compare what events are emitted. What we should get (and which we need to verify) is whether we see a 'finish' event. What should be issued is a finish event after the close event. This is what the code is waiting on (according to the docs, 'finish' is emitted once all resources have been released and close has been emitted). The thing which has me frustrated is that I'm finding the results are intermittent. For example, I ran the script with a size of 200 and it worked fine, but when I ran it with a size of 150, it failed and then running with 200 failed. I've not been able to determine why sometimes it works and sometimes it fails with the same sizes. Once it fails, it appears to fail consistently for a time, but then if you wait and try again, it might work fine. I'm going to modify the scripts to repeat tests multiple times with increasing sizes and see if I can find a repeatable case. All I have been able to verify so far is no errors with versions 14.0 or less.

[theophilusx]

I don't think the missing 'close' event has any relevance. The hanging issue exists with buffers written directly via write() without an intermediate readStream. I have added another script tools/lowlevel-buffer-put-test.js which also turns on ssh2 debugging. It looks like, for some unknown reason, at times, ssh2/ssh2-streams is not returning a STATUS after data is written to the sftp writeStream. This doesn't appear to always happen, but can be reliably triggered if you start with a buffer size of at least 200k. Weird thing is that if I start with a buffer size of 90k and then repeatably put buffers with increasing sizes (by 10k), it won't fail at 200k - in fact, I've not been able to get it to fail when starting at 90 and increasing up 1000 times!. The new script takes 3 arguments: starting size in k, number of runs and path to remote directory to write the files. It will generate a new buffer for each run, increasing the size by 10k each time. When I run the script as follows lowlevel-buffer-put-test.js 100 20 /remote/dir -> works lowlevel-buffer-put-test.js 200 20 /remote/dir -> hangs lowlevel-buffer-put-test.js 300 20 /remote/dir -> works lowlevel-buffer-put-test.js 400 20 /remote/dir -> hangs lowlevel-buffer-put-test.js 500 20 /remote/dir -> works lowlevel-buffer-put-test.js 600 20 /remote/dir -> hangs Notice that with 20 runs and an increase of 10k each run, there is overlap in sizes between the different runs when increasing starting size by 100k. I've also noticed that if it keeps working and I cannot generate an error, even with sizes which previously generated an error, deleting all the files from the remote directory already uploaded seems to 'reset' things and the error will happen again. To muddy the waters further, if a script hangs and I kill it and then run it again immediately, more often than not it will then work or work after 4 or 5 attempts. I also tried testing with a destination of localhost and was not able to reproduce the error with any buffer size. With node v14.1 or less, it works reliably every time. With 14.2 -> 14.7, I see the hanging behaviour. I'm testing against a virtual box image running Arch Linux and a remote sftp server running RedHat on a remote network. The hanging behaviour is observed on both systems. I'm going to try testing with some of the other connection options set e.g. force ipv4, ipv6, compression, no compression etc and see if anything else shows up. If you are also seeing errors with the above script, would you mind logging an issue against ssh2-streams? I will update the issue I already have logged. Need to stress the issue is intermittent. I wouldn't be surprised if you find different sizes reliably trigger the issue to the ones I've observed.

[p-j]

Seems the root cause could be here nodejs/node#32887 (comment)