Hang after sftp.fastPut

[cinderblock]

~80% of the time I call stfp.fastPut(...) since upgrading to Node 12, the promise never resolves. I've tried adding debugging/step function (which does not fire when it hangs) but haven not figured out why it's hanging. I can leave it "hung" for hours to no avail. Yet 20% of the time it "just works". It seems like it might hang more on a very fast/low latency connection but I haven't been able to really confirm that difference. Has anyone else seen problems like this?

PS, this is on Windows 10.

[cinderblock]

Testing this more, it seems I can't even use sftp.writeFile. The same "hanging" happens.

I can confirm I am reading the local file with no trouble.

I can also manually write to the files on the remote system with the same permissions that I'm using over the ssh connection.

When the transfer "hangs", the files on the remote are left in one of a couple states, seemingly randomly:

1. Target file is empty
2. Target file has correct new contents

Of note, I am transferring multiple files. I used to start the fastPuts concurrently and await them all together. I was worried that was causing a problem and have since switched to serially transfering the changes. This has had no effect on the success of the transfers.

Of note, it never hangs on anything but the first transfer. If the first file transfer completes successfully and doesn't "hang", all subsequent transfers work.

I have tried adding .on('error', ...) handlers anywhere I can on my code. I've also tried adding them to the library source files in node_modules trying to catch any error that might have been missed to no avail.

[cinderblock]

Just tried running over a connection with some latency and it works 100% of the time. Sounds like there is a race condition that is happening. Maybe this is related to #34?

Adding compress option also seems to fix the problem.

[tjdavenport]

I ran into something possibly similar. For me, fastPut was sporadically never resolving or rejecting and tended to hang on larger files more often. After some debugging I noticed the step callback was being invoked hundreds if not thousands of times per second. By increasing the chunkSize from the default 3200 to 1240000 I was able to alleviate the step calls to something more sane and as a result fastPut seemed to resolve correctly after reaching completion. My guess is something inside this module locks up (reasonably) when the step function is obnoxiously abused by a low chunkSize. It was pretty cool to see Node being too fast for its own good :]

tl:dr tweak the chunkSize option and see if your problem changes. Hopefully that works for you because using the vanilla ssh2 module without promises is god awful.

[cinderblock]

@tjdavenport Hmmm, thanks for in info. Interestingly, my problem is rearing its head with just a single small file (less than one full default chunk).

Yeah, I've considered looking at using ssh2 directly, maybe with manually wrapping each used method with promisify. But seems like too much trouble!

[dhbahr]

@cinderblock @tjdavenport I seem to be experiencing the same issue after upgrading from Node 8.10 to 10.x in a AWS lambda function (putFile just doesn't respond at all). Did you guys figure out a way to overcome this?

[cinderblock]

@dhbahr Have you tried the compress option? I think it's a race condition and adding a little bit of extra work on one reliably slows it down just enough.

[dhbahr]

@cinderblock thanks for the suggestion. I did indeed try setting the compress option to true, still the handhsake times out. I also passed the regular console.log as debug and got this:

2020-02-26T09:28:41.874Z    5ce07cb6-fcb6-481e-87ce-43a3b1a27932    INFO    [Arguments] {
  '0': 'ssh',
  '1': 'beforeconnect',
  '2':
   SSHConnection {
     domain: null,
     _events:
      [Object: null prototype] {
        ssh: [Function: bound ],
        tunnel: [Function: bound ],
        'ssh:disconnect': [Function: disconnectCb],
        'ssh:continue': [Function: continueCb] },
     _eventsCount: 4,
     _maxListeners: undefined,
     activeTunnels: {},
     '__$connectPromise': null,
     __retries: 1,
     __err: null,
     __sftp: null,
     __x11: null,
     sshConnection: null,
     config:
      { reconnect: true,
        port: '22',
        reconnectTries: 10,
        reconnectDelay: 5000,
        host: 'xxxx.xxxxxxxx.com',
        username: 'xxxxx',
        password: '***********',
        privateKey: undefined,
        passphrase: undefined,
        readyTimeout: '5000',
        compress: true,
        debug: [Function],
        uniqueId: 'xxxxx@xxxx.xxxxxxxx.com:22' },
     __sshTunnels: [ [SSH2Promise] ] },
  '3': undefined }

and

2020-02-26T09:29:27.055Z    5ce07cb6-fcb6-481e-87ce-43a3b1a27932    INFO    [Arguments] {
  '0': 'ssh',
  '1': 'disconnect',
  '2':
   SSHConnection {
     domain: null,
     _events:
      [Object: null prototype] {
        ssh: [Function: bound ],
        tunnel: [Function: bound ],
        'ssh:disconnect': [Function: disconnectCb],
        'ssh:continue': [Function: continueCb] },
     _eventsCount: 4,
     _maxListeners: undefined,
     activeTunnels: {},
     '__$connectPromise': Promise { <pending> },
     __retries: 1,
     __err: null,
     __sftp: null,
     __x11: null,
     sshConnection:
      Client {
        domain: null,
        _events: [Object],
        _eventsCount: 6,
        _maxListeners: undefined,
        config: [Object],
        _readyTimeout:
         Timeout {
           _called: true,
           _idleTimeout: 20000,
           _idlePrev: null,
           _idleNext: null,
           _idleStart: 313696,
           _onTimeout: [Function],
           _timerArgs: undefined,
           _repeat: null,
           _destroyed: false,
           [Symbol(unrefed)]: false,
           [Symbol(asyncId)]: 828,
           [Symbol(triggerId)]: 0 },
        _channels: {},
        _callbacks: [],
        _forwarding: {},
        _forwardingUnix: {},
        _acceptX11: 0,
        _agentFwdEnabled: false,
        _curChan: -1,
        _remoteVer: '0',
        _sshstream: [SSH2Stream],
        _sock: [Socket],
        _resetKA: [Function: resetKA] },
     config:
      { reconnect: true,
        port: '22',
        reconnectTries: 10,
        reconnectDelay: 5000,
        host: 'xxxx.xxxxxxxx.com',
        username: 'xxxxx',
        password: '***********',
        privateKey: undefined,
        passphrase: undefined,
        readyTimeout: '5000',
        compress: true,
        debug: [Function],
        uniqueId: 'xxxxx@xxxx.xxxxxxxx.com:22' },
     __sshTunnels: [ [SSH2Promise] ] },
  '3':
   { err:
      { Error: Timed out while waiting for handshake
          at Timeout._onTimeout (/var/task/node_modules/ssh2-promise/node_modules/ssh2/lib/client.js:695:19)
          at ontimeout (timers.js:436:11)
          at tryOnTimeout (timers.js:300:5)
          at listOnTimeout (timers.js:263:5)
          at Timer.processTimers (timers.js:223:10) level: 'client-timeout' } } }

I am no expert in terms of SSH or SFTP, but I find it weird that it times out on the disconnect (again, it could very well be THE place to timeout). It is also very strange that the 8.10 runtime does not fail ...

[sanketbajoria]

@cinderblock @tjdavenport @dhbahr We have upgraded to ssh2 1.1.0 version, Most of the issue, should be resolved.