[SOLVED] put hangs on bigger files to certain hostings

[ljacho]

If I am trying to upload small file colors.js everything works like a breeze. As soon as I want to do the same with main.js. Put hangs.

-rw-rw-r-- 1 sbtge sbtge   167 Aug 15 22:42 colors.js
-rw-rw-rw- 1 sbtge sbtge 11833 Aug 15 22:49 main.js

Here is the log.

[2021-08-15T22:49:10.698] INFO:   🔼 [SFTPClient] uploading main.js
[2021-08-15T22:49:10.698] CLIENT[sftp]: put: Adding temp event listeners
[2021-08-15T22:49:10.699] Outbound: Sending CHANNEL_DATA (r:0, 63)
[2021-08-15T22:49:10.699] SFTP: Outbound: Buffered OPEN
[2021-08-15T22:49:10.699] CLIENT[sftp]: put source is a stream
[2021-08-15T22:49:10.731] Inbound: CHANNEL_DATA (r:0, 17)
[2021-08-15T22:49:10.732] SFTP: Inbound: Received HANDLE (id:0)
[2021-08-15T22:49:10.732] Outbound: Sending CHANNEL_DATA (r:0, 25)
[2021-08-15T22:49:10.732] SFTP: Outbound: Buffered FSETSTAT
[2021-08-15T22:49:10.765] Inbound: CHANNEL_DATA (r:0, 28)
[2021-08-15T22:49:10.765] SFTP: Inbound: Received STATUS (id:1, 0, "Success")
[2021-08-15T22:49:10.766] Outbound: Sending CHANNEL_DATA (r:0, 7320)
[2021-08-15T22:49:10.766] SFTP: Outbound: Sent WRITE (id:2)
[2021-08-15T22:49:12.645] Outbound: Sending ping (GLOBAL_REQUEST: keepalive@openssh.com)
[2021-08-15T22:49:14.645] Outbound: Sending ping (GLOBAL_REQUEST: keepalive@openssh.com)
[2021-08-15T22:49:16.645] Outbound: Sending ping (GLOBAL_REQUEST: keepalive@openssh.com)
[2021-08-15T22:49:18.646] Outbound: Sending ping (GLOBAL_REQUEST: keepalive@openssh.com)
[2021-08-15T22:49:20.647] Outbound: Sending ping (GLOBAL_REQUEST: keepalive@openssh.com)
[2021-08-15T22:49:22.647] Outbound: Sending ping (GLOBAL_REQUEST: keepalive@openssh.com)
[2021-08-15T22:49:24.647] Outbound: Sending ping (GLOBAL_REQUEST: keepalive@openssh.com)
[2021-08-15T22:49:26.648] Outbound: Sending ping (GLOBAL_REQUEST: keepalive@openssh.com)
[2021-08-15T22:49:28.648] Outbound: Sending ping (GLOBAL_REQUEST: keepalive@openssh.com)
[2021-08-15T22:49:30.648] Outbound: Sending ping (GLOBAL_REQUEST: keepalive@openssh.com)
[2021-08-15T22:49:32.649] Outbound: Sending ping (GLOBAL_REQUEST: keepalive@openssh.com)
[2021-08-15T22:49:34.649] Outbound: Sending ping (GLOBAL_REQUEST: keepalive@openssh.com)
[2021-08-15T22:49:36.649] Outbound: Sending ping (GLOBAL_REQUEST: keepalive@openssh.com)
[2021-08-15T22:49:38.650] Outbound: Sending ping (GLOBAL_REQUEST: keepalive@openssh.com)
[2021-08-15T22:49:40.650] Outbound: Sending ping (GLOBAL_REQUEST: keepalive@openssh.com)
[2021-08-15T22:49:42.650] Outbound: Sending ping (GLOBAL_REQUEST: keepalive@openssh.com)
[2021-08-15T22:49:44.650] Outbound: Sending ping (GLOBAL_REQUEST: keepalive@openssh.com)
[2021-08-15T22:49:46.650] Outbound: Sending ping (GLOBAL_REQUEST: keepalive@openssh.com)
[2021-08-15T22:49:48.650] Outbound: Sending ping (GLOBAL_REQUEST: keepalive@openssh.com)
[2021-08-15T22:49:50.651] Outbound: Sending ping (GLOBAL_REQUEST: keepalive@openssh.com)
[2021-08-15T22:49:52.652] CLIENT[sftp]: put: Handling error: Keepalive timeout
[2021-08-15T22:49:52.652] CLIENT[sftp]: put: handled error with reject
[2021-08-15T22:49:52.652] CLIENT[sftp]: Global: Ignoring handled error
[2021-08-15T22:49:52.652] CLIENT[sftp]: put: Removing temp event listeners
[2021-08-15T22:49:52.653] Error: put: Keepalive timeout
    at fmtError (/home/sbtge/workspace/1-lab/ftp-syncer/dist/index.js:3767:22)
    at Client.fn (/home/sbtge/workspace/1-lab/ftp-syncer/dist/index.js:3782:20)
    at Client.emit (node:events:388:22)
    at Timeout.sendKA (/home/sbtge/workspace/1-lab/ftp-syncer/node_modules/ssh2/lib/client.js:662:16)
    at listOnTimeout (node:internal/timers:556:17)
    at processTimers (node:internal/timers:499:7)

I am using ssh2-sftp-cllient: 7.0.1 and node v. 15.3.0.

[theophilusx]

It shouldn't just hang - log shows you are being sent a rejected promise. I suspect your code is not handling the put() promise correctly. Can you create a minimal example which reproduces the issue and send the code. BTW node v15.4 is an old development version - really should be using a release version or at least the latest in that development series (i.e. 15.14.0 or better 16.6.2 - especially given important security vulnerabilities were recently fixed in all node versions from v12 - v16. Ladislav Jacho ***@***.***> writes:

…

If I am trying to upload small file colors.js everything works like a breeze. As soon as I want to do the same with main.js. Put hangs. -rw-rw-r-- 1 sbtge sbtge 167 Aug 15 22:42 colors.js -rw-rw-rw- 1 sbtge sbtge 11833 Aug 15 22:49 main.js Here is the log. [2021-08-15T22:49:10.698] INFO: 🔼 [SFTPClient] uploading main.js [2021-08-15T22:49:10.698] CLIENT[sftp]: put: Adding temp event listeners [2021-08-15T22:49:10.699] Outbound: Sending CHANNEL_DATA (r:0, 63) [2021-08-15T22:49:10.699] SFTP: Outbound: Buffered OPEN [2021-08-15T22:49:10.699] CLIENT[sftp]: put source is a stream [2021-08-15T22:49:10.731] Inbound: CHANNEL_DATA (r:0, 17) [2021-08-15T22:49:10.732] SFTP: Inbound: Received HANDLE (id:0) [2021-08-15T22:49:10.732] Outbound: Sending CHANNEL_DATA (r:0, 25) [2021-08-15T22:49:10.732] SFTP: Outbound: Buffered FSETSTAT [2021-08-15T22:49:10.765] Inbound: CHANNEL_DATA (r:0, 28) [2021-08-15T22:49:10.765] SFTP: Inbound: Received STATUS (id:1, 0, "Success") [2021-08-15T22:49:10.766] Outbound: Sending CHANNEL_DATA (r:0, 7320) [2021-08-15T22:49:10.766] SFTP: Outbound: Sent WRITE (id:2) [2021-08-15T22:49:12.645] Outbound: Sending ping (GLOBAL_REQUEST: ***@***.***) [2021-08-15T22:49:14.645] Outbound: Sending ping (GLOBAL_REQUEST: ***@***.***) [2021-08-15T22:49:16.645] Outbound: Sending ping (GLOBAL_REQUEST: ***@***.***) [2021-08-15T22:49:18.646] Outbound: Sending ping (GLOBAL_REQUEST: ***@***.***) [2021-08-15T22:49:20.647] Outbound: Sending ping (GLOBAL_REQUEST: ***@***.***) [2021-08-15T22:49:22.647] Outbound: Sending ping (GLOBAL_REQUEST: ***@***.***) [2021-08-15T22:49:24.647] Outbound: Sending ping (GLOBAL_REQUEST: ***@***.***) [2021-08-15T22:49:26.648] Outbound: Sending ping (GLOBAL_REQUEST: ***@***.***) [2021-08-15T22:49:28.648] Outbound: Sending ping (GLOBAL_REQUEST: ***@***.***) [2021-08-15T22:49:30.648] Outbound: Sending ping (GLOBAL_REQUEST: ***@***.***) [2021-08-15T22:49:32.649] Outbound: Sending ping (GLOBAL_REQUEST: ***@***.***) [2021-08-15T22:49:34.649] Outbound: Sending ping (GLOBAL_REQUEST: ***@***.***) [2021-08-15T22:49:36.649] Outbound: Sending ping (GLOBAL_REQUEST: ***@***.***) [2021-08-15T22:49:38.650] Outbound: Sending ping (GLOBAL_REQUEST: ***@***.***) [2021-08-15T22:49:40.650] Outbound: Sending ping (GLOBAL_REQUEST: ***@***.***) [2021-08-15T22:49:42.650] Outbound: Sending ping (GLOBAL_REQUEST: ***@***.***) [2021-08-15T22:49:44.650] Outbound: Sending ping (GLOBAL_REQUEST: ***@***.***) [2021-08-15T22:49:46.650] Outbound: Sending ping (GLOBAL_REQUEST: ***@***.***) [2021-08-15T22:49:48.650] Outbound: Sending ping (GLOBAL_REQUEST: ***@***.***) [2021-08-15T22:49:50.651] Outbound: Sending ping (GLOBAL_REQUEST: ***@***.***) [2021-08-15T22:49:52.652] CLIENT[sftp]: put: Handling error: Keepalive timeout [2021-08-15T22:49:52.652] CLIENT[sftp]: put: handled error with reject [2021-08-15T22:49:52.652] CLIENT[sftp]: Global: Ignoring handled error [2021-08-15T22:49:52.652] CLIENT[sftp]: put: Removing temp event listeners [2021-08-15T22:49:52.653] Error: put: Keepalive timeout at fmtError (/home/sbtge/workspace/1-lab/ftp-syncer/dist/index.js:3767:22) at Client.fn (/home/sbtge/workspace/1-lab/ftp-syncer/dist/index.js:3782:20) at Client.emit (node:events:388:22) at Timeout.sendKA (/home/sbtge/workspace/1-lab/ftp-syncer/node_modules/ssh2/lib/client.js:662:16) at listOnTimeout (node:internal/timers:556:17) at processTimers (node:internal/timers:499:7) I am using ssh2-sftp-cllient: 7.0.1 and node v. 15.3.0. — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub, or unsubscribe. Triage notifications on the go with GitHub Mobile for iOS or Android.

[ljacho]

Thank you for your quick answer. I changed the node to 16.6.2 as you advised. Problem persists.

Here is a simplified version of the code:

index.ts :

const sFTP = new SFTP();
sFTP.pub('/home/myUser/test/main.js');

sftp.ts:

import Client from 'ssh2-sftp-client';

export default class SFTP {
  constructor() {
     this.options = {
      host: config.sftp.host,
      port: config.sftp.port,
      username: config.sftp.username,
      password: config.sftp.password,
      debug: config.sftp.debug ? console.log : null,
    }
   this.uploadOptions = {
       flags: 'w', // w - write and a - append
      encoding: null, // use null for binary files
      mode: 0o664, // mode to use for created file (rwx)
      autoClose: true, // automatically close the write stream when finished
   }
  }

  public pub(path: string): void {
      const data = fs.createReadStream(path);
      this.client = new Client();
  
      const fileName = path.split('/').pop();
  
      this.client
        .connect(this.options)
        .then(() => {
          console.log('uploading');
          return this.client.put(data, `${config.sftp.remotePath}/${fileName}`, this.uploadOptions);
        })
        .then(() => {
          console.log('uploaded! ending');
          return this.client.end();
        })
        .catch((err) => {
          console.log(`Error: ${err.message}`); // error message will include 'example-client'
        });
    }
}

Code is heavily inspired by your examples. Thank you for any help!

[ljacho]

UPDATE: I found out that files ~3.06 KiB and bigger are not uploading correctly. If I use a client e.g. Filezilla, all files are being uploaded without problems.

[theophilusx]

What do you have in the 'options' and 'uploadOptions' objects? (I don't need password/username/host, just the other settings). What platform is the client running on and do you know what platform the remote sftp server is running on?

[ljacho]

options besides password/username/host I got port 22

and

   uploadOptions = {
       flags: 'w', // w - write and a - append
      encoding: null, // use null for binary files
      mode: 0o664, // mode to use for created file (rwx)
      autoClose: true, // automatically close the write stream when finished
   }

sftp server is running on godaddy - I dont know what platform are they using.

IMPORTANT: I found out that it is not working in WSL2 but on mac x64 it works with bigger files!

Do you have an idea where could be the problem?

[theophilusx]

This is not an issue I am able to reproduce with any of my test servers. My tests include transfer of files in sizes up to 1Gb and include file checksums to verify the data is being transferred correctly. This indicates it is either an issue local to your network or some special edge case associated with the sftp server you are attempting to upload to. I have seen similar problems when going through a deep packet inspection firewall (such as Palo Alto firewalls). With such firewalls, it takes a few data packets before the firewall has sufficient data to inspect and make a call regarding whether to permit the traffic to continue. When the firewall decides to block the data, it tends to just drop it and not report any errors (because it doesn't want to give any hints/information to potentially malicious users). This isn't to say this is your problem, but merely an example of the types of problems you can encounter. It can be difficult to diagnose because other sftp programs will work (the Palo Alto works based on traffic signatures and different software exhibits different signatures). In one case I had, I could only get the data uploaded if I explicitly told the remote sftp server not to use compression. The firewall allowed uncompressed packets through, but not compressed ones. I had to wait until the network admins updated the firewall signatures before I was able to use compression. One thing you could try is uploading to an sftp server which is on your local network (and presumably does not need to go through any firewalls) and see if you observe the same issue. The other thing you will need to do if you cannot isolate the issue is write a simple script using just the ssh2 module and verify the issue with just that. If it still exists, you will need to log an issue with the ssh2 maintainers. The ssh2-sftp-client is really just a wrapper around the ssh2 module, providing a more abstracted and promise based API. If there is an issue with how it is processing the data upload, there is little I can do form the ssh2-sftp-client layer. There are sample scripts in the validation directory which you can use as a template. If you right a script which only uses ssh2 and it works, then please let me know as that would indicate the issue is in the ssh2-sftp-layer. However, this is unlikely (you would be the first to find such an issue :-;)

[ljacho]

thank you for deeper explanation! I will try to continue with this for a bit ;)

[theophilusx]

No idea. I wouldn't be surprised if it wasn't something particular to the network stack and WSL. I'd install node on native windows and see if that works. Note that I don't use windows. I do run the test suite on a windows 10 system and I do test against a Windows based sftp server, but I have little experience with that platform. My money would be that it is to do with the WSL layer - this is effectively a virtual machine where they are doing some network bridging across the main host network stack and that could introduce all sorts of weirdness. BTW I don't think you need the put options - they are effectively the defaults anyway. Likewise with setting port as 22 is the default. In general, I think it is better not to supply options unless you need to change them from the default.

[ljacho]

gotcha!

look:

I can upload main.js (that bigger file) to another sftp server running on digital ocean vps without any problems

• from mac x64
• from wsl2

I can upload main.js to godaddy

• from mac x64
• from wsl2 - Ubuntu
• UPDATE: Ubuntu 20.04.1 LTS

even linux sftp CLI utility hangs with uploading main.js from WSL2 - Ubuntu & Ubuntu 20.04.1 LTS to godaddy!

we can close this as it's not the problem of ssh2-sftp-client at all

[ljacho]

definitely not a problem of ssh2-sftp-client

I prepared answer for all people coming here.

Short Answer
You probably have an MTU/fragmentation problem. For each network interface on both client and server set the MTU to 576, eg ifconfig eth0 mtu 576. If the problem goes away, read on.

Long Answer
Long answer: At each routing hop, IP packets bigger than the outgoing interface's Maximum Transmission Unit (MTU) get fragmented. Only the first fragment has TCP port numbers. Firewalls often behave badly in the presence of packet fragmentation, dropping everything but the first fragment since the subsequent ones can't be matched against the firewall rules. Some NAT configuration (eg many-to-one NAT or port address translation) can't match the fragments against their translation state tables.

Arguably, such devices should perform packet reassembly first so as to properly consider fragmented packets. However, this is more complicated and so is often not done. Also, this feature would raise a possible starvation attack against the packet filter, by sending many bogus initial fragments and causing the device to store them for reassembly with subsequent packets which will never come.

Logging in and using the shell will normally generate relatively small packets, and so the initial connection proceeds normally ; however if do you something that generates a lot of data (eg cat'ing a big file or starting an X Windows application), you may generate a packet bigger than the MTU.

Let's say it's a 1500 byte IP packet and the router has 2 different MTU's (say 1500 & 1484) and no firewall. When the router goes to forward it, the packet is too big for the interface MTU (1484), so the router breaks it into 2 fragments, 0 and 1. Fragment 0 contains the first 1484 bytes (including the TCP source and dest ports) and fragment 1 contains the remaining 16 bytes. Both fragments are sent on to their destinations.

When the first fragment reaches its target, it's held by the IP stack until the remaining fragments arrive, at which time the IP packet is reassembled and passed up the stack to TCP. If all fragments are not received by the timeout, the entire IP packet is discarded and an ICMP "timeout during reassembly" error is sent back.

Now add your firewall, which drops fragment 1. Your 1500 byte IP packet times out during reassembly and TCP retries, by sending another 1500 byte packet. Repeat. Eventually, TCP will time out and you'll get a connection termination.

IP stack parameters (such as Path MTU Discovery) and external variables (such as the MTU's of all the hops between hosts) can also affect whether or not a given connection will have this problem.

source: snailbook.com

temporary solution:

ip link set eth0 mtu 1400

[theophilusx]

Thanks, I'll add it to the 'Troubleshooting' section of the README. In the 'old days', it was common to have to set an MTU of 1400 whenever you needed to interact with Windows/MS-DOS based systems. I had completely forgotten that as it has been some time since I've seen this issue.