search

mscdex / ssh2

SSH2 client and server modules written in pure JavaScript for node.js
MIT License
5.51k stars 663 forks source link

"sftp: Unexpected end event raised by server" after inbound request for a channel window adjust #1161

Closed kelly1266 closed 2 years ago

kelly1266 commented 2 years ago

Hi there, I am facing a strange issue where I am trying to connect to an sftp server and grab a file. Im able to connect to the sftp server but it makes a request to adjust the channel window size and then fails 5 minutes after receiving the request. I have been able to connect to multiple other servers without issue, some of which also made requests to adjust the window size and this is the first instance where its failed. I think this may be some sort of misconfiguration on the SFTP server but I have no idea what that could be. Im hoping that someone more familiar with the project might be able to help me figure out what is going wrong here. Any suggestions as to what I could try?

Here are the relevant logs:

"Handshake completed"
"Outbound: Sending SERVICE_REQUEST (ssh-userauth)"
"Inbound: Received SERVICE_ACCEPT (ssh-userauth)"
"Outbound: Sending USERAUTH_REQUEST (none)"
"Inbound: Received USERAUTH_FAILURE (publickey,password)"
"Client: none auth failed"
"Outbound: Sending USERAUTH_REQUEST (publickey -- check)"
"Inbound: Received USERAUTH_PK_OK"
"Outbound: Sending USERAUTH_REQUEST (publickey)"
"Inbound: Received USERAUTH_SUCCESS"
"CLIENT[sftp]: Removing listener from ready"
"CLIENT[sftp]: sftp: Removing end listener"
"CLIENT[sftp]: sftp: Removing close listener"
"CLIENT[sftp]: sftp: Removing error listener"
"Outbound: Sending CHANNEL_OPEN (r:0, session)"
"Inbound: CHANNEL_OPEN_CONFIRMATION (r:0, s:0)"
"Outbound: Sending CHANNEL_REQUEST (r:0, subsystem: sftp)"
"Inbound: CHANNEL_SUCCESS (r:0)"
"Inbound: CHANNEL_WINDOW_ADJUST (r:0, 524288)"
"Socket ended"
"CLIENT[sftp]: sftp: Unexpected end event raised by server"
"Socket closed"
"CLIENT[sftp]: sftp: Unexpected close event raised by server"
"CLIENT[sftp]: SFTP Channel Error: Received unexpected SFTP session termination"
mscdex commented 2 years ago

Those "CLIENT[sftp]" messages are not coming from ssh2, so I can't help you with those. Are you using a third party module instead of ssh2? If so, can you retry with using ssh2 directly and confirm that the problem still exists?

richard-peters commented 2 years ago

Hi, I'm having the same issue - I'm testing using the example sftp call on the SSH2 readme (have taken ssh2-sftp-client out of the loop).

I'm connecting with a private key and passphrase.

I'm able to connect via a CLI sftp call.

Is there anything I can provide to help debug?

lman-group1-sha1
->  Handshake: KEX algorithm: diffie-hellman-group-exchange-sha256
->  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: ssh-rsa,ssh-dss
->  Handshake: Host key format: ssh-rsa
->  Handshake: (local) C->S cipher: aes128-gcm@openssh.com,aes256-gcm@openssh.com,aes128-ctr,aes192-ctr,chacha20-poly1305@openssh.com,aes256-ctr
->  Handshake: (remote) C->S cipher: aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour,aes192-cbc,aes256-cbc,rijndael-cbc@lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr
->  Handshake: C->S Cipher: aes128-ctr
->  Handshake: (local) S->C cipher: aes128-gcm@openssh.com,aes256-gcm@openssh.com,aes128-ctr,aes192-ctr,chacha20-poly1305@openssh.com,aes256-ctr
->  Handshake: (remote) S->C cipher: aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour,aes192-cbc,aes256-cbc,rijndael-cbc@lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr
->  Handshake: S->C cipher: aes128-ctr
->  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: hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96,hmac-sha2-256,hmac-sha2-512
->  Handshake: C->S MAC: hmac-sha2-256
->  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: hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96,hmac-sha2-256,hmac-sha2-512
->  Handshake: S->C MAC: hmac-sha2-256
->  Handshake: (local) C->S compression: none,zlib@openssh.com,zlib
->  Handshake: (remote) C->S compression: zlib,none
->  Handshake: C->S compression: none
->  Handshake: (local) S->C compression: none,zlib@openssh.com,zlib
->  Handshake: (remote) S->C compression: zlib,none
->  Handshake: S->C compression: none
->  Outbound: Sending KEXDH_GEX_REQUEST
->  Received DH GEX Group
->  Outbound: Sending KEXDH_GEX_INIT
->  Received DH GEX Reply
->  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 SERVICE_ACCEPT (ssh-userauth)
->  Outbound: Sending USERAUTH_REQUEST (none)
->  Inbound: Received USERAUTH_FAILURE (publickey,password)
->  Client: none auth failed
->  Outbound: Sending USERAUTH_REQUEST (publickey -- check)
->  Inbound: Received USERAUTH_PK_OK
->  Outbound: Sending USERAUTH_REQUEST (publickey)
->  Inbound: Received USERAUTH_SUCCESS
Client :: ready
->  Outbound: Sending CHANNEL_OPEN (r:0, session)
->  Inbound: CHANNEL_OPEN_CONFIRMATION (r:0, s:0)
->  Outbound: Sending CHANNEL_REQUEST (r:0, subsystem: sftp)
->  Inbound: CHANNEL_SUCCESS (r:0)
->  Inbound: CHANNEL_WINDOW_ADJUST (r:0, 524288)
mscdex commented 2 years ago

@richard-peters The log you've posted indicates nothing wrong. It just shows that you successfully started an sftp session.

richard-peters commented 2 years ago

Hi @mscdex - thanks for your reply - perhaps my issue is slightly different - the SSH connection is initialising, but I'm unable to get an SFTP connection response.. The "SFTP Client :: ready" console write is never hit.

The private cert and passphrase are being accepted; I suspect this is a config issue on the SFTP server side - interested to know if other users have hit this problem or if there is known workaround. 

const conn = new Client();
conn
  .on("ready", () => {
    console.log("Client :: ready");
    conn.sftp((err, sftp) => {
      if (err) throw err;
      console.log("SFTP Client :: ready");
      sftp.readdir("/", (err, list) => {
        if (err) throw err;
        console.dir(list);
        conn.end();
      });
    });
    ................
mscdex commented 2 years ago

@richard-peters Do you have an 'uncaughtException' event handler on process or similar that might be silently catching your throw err? The callback should definitely be called according to the log you provided.

richard-peters commented 2 years ago

@mscdex - thanks again for replying so quickly. This is my entire script (to try and isolate the issue, I've created a simple test) - I've added some additional logging, but the output remains unchanged:

const fs = require("fs");
const { Client } = require("ssh2");

const conn = new Client();
conn
  .on("ready", () => {
    console.log("Client :: ready");
    conn.sftp((err, sftp) => {
      if (err) {
        console.log('err: ', err);
        throw err;
      }
      console.log("SFTP Client :: ready");
      sftp.readdir("/", (err, list) => {
        if (err) {
          console.log("err: ", err);
          throw err;
        }
        console.dir(list);
        conn.end();
      });
    });
  })
  .on("error", function (err) {
    console.log("error: ", err);
  })
  .connect({
    host: "xx",
    port: "22",
    username: "xx",
    privateKey: fs.readFileSync("xx"),
    passphrase: `xx`,  
    debug: (msg) => {
      console.log("-> ", msg);
    },
  });
mscdex commented 2 years ago

@richard-peters What node version and ssh2 version are you testing with?

richard-peters commented 2 years ago

@mscdex I've tried different versions of both - current node -> 16.0.0, ssh2 -> master branch (was also getting the same issue with an AWS lambda)

mscdex commented 2 years ago

@richard-peters I can't reproduce the issue. Out of curiosity, what is the server's ident string (shown near the beginning of the debug output)?

richard-peters commented 2 years ago

@mscdex

SSH-2.0-SysaxSSH_1.4

Full log:

->  Custom crypto binding available
->  Local ident: 'SSH-2.0-ssh2js1.9.0'
->  Client: Trying XXXXXX on port 22 ...
->  Socket connected
->  Remote ident: 'SSH-2.0-SysaxSSH_1.4'
->  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
->  Handshake: (remote) KEX method: diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group14-sha256,diffie-hellman-group-exchange-sha256,diffie-hellman-group1-sha1
->  Handshake: KEX algorithm: diffie-hellman-group-exchange-sha256
->  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: ssh-rsa,ssh-dss
->  Handshake: Host key format: ssh-rsa
->  Handshake: (local) C->S cipher: aes128-gcm@openssh.com,aes256-gcm@openssh.com,aes128-ctr,aes192-ctr,chacha20-poly1305@openssh.com,aes256-ctr
->  Handshake: (remote) C->S cipher: aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour,aes192-cbc,aes256-cbc,rijndael-cbc@lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr
->  Handshake: C->S Cipher: aes128-ctr
->  Handshake: (local) S->C cipher: aes128-gcm@openssh.com,aes256-gcm@openssh.com,aes128-ctr,aes192-ctr,chacha20-poly1305@openssh.com,aes256-ctr
->  Handshake: (remote) S->C cipher: aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour,aes192-cbc,aes256-cbc,rijndael-cbc@lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr
->  Handshake: S->C cipher: aes128-ctr
->  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: hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96,hmac-sha2-256,hmac-sha2-512
->  Handshake: C->S MAC: hmac-sha2-256
->  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: hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96,hmac-sha2-256,hmac-sha2-512
->  Handshake: S->C MAC: hmac-sha2-256
->  Handshake: (local) C->S compression: none,zlib@openssh.com,zlib
->  Handshake: (remote) C->S compression: zlib,none
->  Handshake: C->S compression: none
->  Handshake: (local) S->C compression: none,zlib@openssh.com,zlib
->  Handshake: (remote) S->C compression: zlib,none
->  Handshake: S->C compression: none
->  Outbound: Sending KEXDH_GEX_REQUEST
->  Received DH GEX Group
->  Outbound: Sending KEXDH_GEX_INIT
->  Received DH GEX Reply
->  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 SERVICE_ACCEPT (ssh-userauth)
->  Outbound: Sending USERAUTH_REQUEST (none)
->  Inbound: Received USERAUTH_FAILURE (publickey,password)
->  Client: none auth failed
->  Outbound: Sending USERAUTH_REQUEST (publickey -- check)
->  Inbound: Received USERAUTH_PK_OK
->  Outbound: Sending USERAUTH_REQUEST (publickey)
->  Inbound: Received USERAUTH_SUCCESS
Client :: ready
->  Outbound: Sending CHANNEL_OPEN (r:0, session)
->  Inbound: CHANNEL_OPEN_CONFIRMATION (r:0, s:0)
->  Outbound: Sending CHANNEL_REQUEST (r:0, subsystem: sftp)
->  Inbound: CHANNEL_SUCCESS (r:0)
->  Inbound: CHANNEL_WINDOW_ADJUST (r:0, 524288)
mscdex commented 2 years ago

@richard-peters The server ident string is "SysaxSSH_1.4" in that case. Have you had success with other servers (or other server types, like OpenSSH)?

richard-peters commented 2 years ago

@mscdex - seems isolated to this specific server.

mscdex commented 2 years ago

@richard-peters Does using the OpenSSH sftp client work when connecting to that same exact problematic server? If so, could you post the output when passing -vvv to the OpenSSH sftp client?

richard-peters commented 2 years ago

@mscdex - it does, yes. Output below.

OpenSSH_8.1p1, LibreSSL 2.7.3
debug1: Reading configuration data /Users/xx/.ssh/config
debug1: Reading configuration data /etc/ssh/ssh_config
debug1: /etc/ssh/ssh_config line 47: Applying options for *
debug2: resolve_canonicalize: hostname xx is address
debug2: ssh_connect_direct
debug1: Connecting to xx [xx] port 22.
debug1: Connection established.
debug1: identity file xx.pem type -1
debug1: identity file xx.pem-cert type -1
debug1: Local version string SSH-2.0-OpenSSH_8.1
debug1: Remote protocol version 2.0, remote software version SysaxSSH_1.4
debug1: no match: SysaxSSH_1.4
debug2: fd 3 setting O_NONBLOCK
debug1: Authenticating to xx:22 as 'xx'
debug3: hostkeys_foreach: reading file "/Users/xx/.ssh/known_hosts"
debug3: record_hostkey: found key type RSA in file /Users/xx/.ssh/known_hosts:18
debug3: load_hostkeys: loaded 1 keys from xx
debug3: order_hostkeyalgs: prefer hostkeyalgs: rsa-sha2-512-cert-v01@openssh.com,rsa-sha2-256-cert-v01@openssh.com,ssh-rsa-cert-v01@openssh.com,rsa-sha2-512,rsa-sha2-256,ssh-rsa
debug3: send packet: type 20
debug1: SSH2_MSG_KEXINIT sent
debug3: receive packet: type 20
debug1: SSH2_MSG_KEXINIT received
debug2: local client KEXINIT proposal
debug2: KEX algorithms: 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,ext-info-c
debug2: host key algorithms: rsa-sha2-512-cert-v01@openssh.com,rsa-sha2-256-cert-v01@openssh.com,ssh-rsa-cert-v01@openssh.com,rsa-sha2-512,rsa-sha2-256,ssh-rsa,ecdsa-sha2-nistp256-cert-v01@openssh.com,ecdsa-sha2-nistp384-cert-v01@openssh.com,ecdsa-sha2-nistp521-cert-v01@openssh.com,ssh-ed25519-cert-v01@openssh.com,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,ssh-ed25519
debug2: ciphers ctos: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com
debug2: ciphers stoc: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com
debug2: MACs ctos: 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
debug2: MACs stoc: 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
debug2: compression ctos: none,zlib@openssh.com,zlib
debug2: compression stoc: none,zlib@openssh.com,zlib
debug2: languages ctos: 
debug2: languages stoc: 
debug2: first_kex_follows 0 
debug2: reserved 0 
debug2: peer server KEXINIT proposal
debug2: KEX algorithms: diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group14-sha256,diffie-hellman-group-exchange-sha256,diffie-hellman-group1-sha1
debug2: host key algorithms: ssh-rsa,ssh-dss
debug2: ciphers ctos: aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour,aes192-cbc,aes256-cbc,rijndael-cbc@lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr
debug2: ciphers stoc: aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour,aes192-cbc,aes256-cbc,rijndael-cbc@lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr
debug2: MACs ctos: hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96,hmac-sha2-256,hmac-sha2-512
debug2: MACs stoc: hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96,hmac-sha2-256,hmac-sha2-512
debug2: compression ctos: zlib,none
debug2: compression stoc: zlib,none
debug2: languages ctos: 
debug2: languages stoc: 
debug2: first_kex_follows 0 
debug2: reserved 0 
debug1: kex: algorithm: diffie-hellman-group-exchange-sha256
debug1: kex: host key algorithm: ssh-rsa
debug1: kex: server->client cipher: aes128-ctr MAC: hmac-sha2-256 compression: none
debug1: kex: client->server cipher: aes128-ctr MAC: hmac-sha2-256 compression: none
debug3: send packet: type 34
debug1: SSH2_MSG_KEX_DH_GEX_REQUEST(2048<8192<8192) sent
debug3: receive packet: type 31
debug1: got SSH2_MSG_KEX_DH_GEX_GROUP
debug2: bits set: 1073/2048
debug3: send packet: type 32
debug1: SSH2_MSG_KEX_DH_GEX_INIT sent
debug3: receive packet: type 33
debug1: got SSH2_MSG_KEX_DH_GEX_REPLY
debug1: Server host key: ssh-rsa SHA256:xxxxxxxx
debug3: hostkeys_foreach: reading file "/Users/xx/.ssh/known_hosts"
debug3: record_hostkey: found key type RSA in file /Users/xx/.ssh/known_hosts:18
debug3: load_hostkeys: loaded 1 keys from xxxxx
debug1: Host 'xxx' is known and matches the RSA host key.
debug1: Found key in /Users/xx/.ssh/known_hosts:18
debug2: bits set: 1008/2048
debug3: send packet: type 21
debug2: set_newkeys: mode 1
debug1: rekey out after 4294967296 blocks
debug1: SSH2_MSG_NEWKEYS sent
debug1: expecting SSH2_MSG_NEWKEYS
debug3: receive packet: type 21
debug1: SSH2_MSG_NEWKEYS received
debug2: set_newkeys: mode 0
debug1: rekey in after 4294967296 blocks
debug1: Will attempt key: xxxx.pem  explicit
debug2: pubkey_prepare: done
debug3: send packet: type 5
debug3: receive packet: type 6
debug2: service_accept: ssh-userauth
debug1: SSH2_MSG_SERVICE_ACCEPT received
debug3: send packet: type 50
debug3: receive packet: type 51
debug1: Authentications that can continue: publickey,password
debug3: start over, passed a different list publickey,password
debug3: preferred publickey,keyboard-interactive,password
debug3: authmethod_lookup publickey
debug3: remaining preferred: keyboard-interactive,password
debug3: authmethod_is_enabled publickey
debug1: Next authentication method: publickey
debug1: Trying private key: xxxx.pem
Enter passphrase for key 'xxxx.pem': 
debug3: sign_and_send_pubkey: RSA SHA256:xxxxxx
debug3: sign_and_send_pubkey: signing using ssh-rsa
debug3: send packet: type 50
debug2: we sent a publickey packet, wait for reply
debug3: receive packet: type 52
debug1: Authentication succeeded (publickey).
Authenticated to xxxxx ([xxxx]:22).
debug2: fd 4 setting O_NONBLOCK
debug3: fd 5 is O_NONBLOCK
debug1: channel 0: new [client-session]
debug3: ssh_session2_open: channel_new: 0
debug2: channel 0: send open
debug3: send packet: type 90
debug1: Entering interactive session.
debug1: pledge: network
debug3: receive packet: type 91
debug2: channel_input_open_confirmation: channel 0: callback start
debug2: fd 3 setting TCP_NODELAY
debug3: ssh_packet_set_tos: set IP_TOS 0x20
debug2: client_session2_setup: id 0
debug1: Sending environment.
debug3: Ignored env SHELL
debug3: Ignored env COLORTERM
debug3: Ignored env XPC_FLAGS
debug3: Ignored env NVM_INC
debug3: Ignored env TERM_PROGRAM_VERSION
debug3: Ignored env JAVA_HOME
debug3: Ignored env __CFBundleIdentifier
debug3: Ignored env SSH_AUTH_SOCK
debug3: Ignored env SDKMAN_CANDIDATES_DIR
debug3: Ignored env EDITOR
debug3: Ignored env PWD
debug3: Ignored env LOGNAME
debug3: Ignored env LaunchInstanceID
debug3: Ignored env VSCODE_GIT_ASKPASS_NODE
debug3: Ignored env COMMAND_MODE
debug3: Ignored env HOME
debug1: Sending env LANG = en_GB.UTF-8
debug2: channel 0: request env confirm 0
debug3: send packet: type 98
debug3: Ignored env SDKMAN_VERSION
debug3: Ignored env TMPDIR
debug3: Ignored env GIT_ASKPASS
debug3: Ignored env M2_HOME
debug3: Ignored env NVM_DIR
debug3: Ignored env VSCODE_GIT_ASKPASS_EXTRA_ARGS
debug3: Ignored env TERM
debug3: Ignored env USER
debug3: Ignored env VSCODE_GIT_IPC_HANDLE
debug3: Ignored env SDKMAN_DIR
debug3: Ignored env DISPLAY
debug3: Ignored env SHLVL
debug3: Ignored env NVM_CD_FLAGS
debug3: Ignored env SDKMAN_CANDIDATES_API
debug3: Ignored env XPC_SERVICE_NAME
debug3: Ignored env VSCODE_GIT_ASKPASS_MAIN
debug3: Ignored env PATH
debug3: Ignored env ORIGINAL_XDG_CURRENT_DESKTOP
debug3: Ignored env SDKMAN_PLATFORM
debug3: Ignored env NVM_BIN
debug3: Ignored env OLDPWD
debug3: Ignored env GOPATH
debug3: Ignored env __CF_USER_TEXT_ENCODING
debug3: Ignored env TERM_PROGRAM
debug3: Ignored env _
debug1: Sending subsystem: sftp
debug2: channel 0: request subsystem confirm 1
debug3: send packet: type 98
debug2: channel_input_open_confirmation: channel 0: callback done
debug2: channel 0: open confirm rwindow 0 rmax 32768
debug3: receive packet: type 99
debug2: channel_input_status_confirm: type 99 id 0
debug2: subsystem request accepted on channel 0
debug2: channel 0: rcvd adjust 524288
debug2: Remote version: 3
Connected to xxx.
debug3: Sent message fd 3 T:16 I:1
debug3: SSH_FXP_REALPATH . -> / size 0
sftp>
mscdex commented 2 years ago

I think I might see what's happening. I'm betting the other side is opening the channel with an empty window and we aren't trying to send out buffered data once the other sides increases the channel window.

@richard-peters @kelly1266 Can you try this patch on top of ssh2 master?:

diff --git a/lib/protocol/SFTP.js b/lib/protocol/SFTP.js
index 029fefe..a7fc4f9 100644
--- a/lib/protocol/SFTP.js
+++ b/lib/protocol/SFTP.js
@@ -2502,7 +2502,8 @@ function tryWritePayload(sftp, payload) {
     return;

   if (outgoing.window === 0) {
-    sftp._waitWindow = true; // XXX: Unnecessary?
+    sftp._waitWindow = true;
+    sftp._chunkcb = drainBuffer;
     return payload;
   }
kelly1266 commented 2 years ago

@mscdex Sure thing, I can try give it a try tomorrow. Also, apologies I forgot to respond to your initial question:

Are you using a third party module instead of ssh2? If so, can you retry with using ssh2 directly and confirm that the problem still exists?

The project I am working on uses this wrapper. I should be able to retry the connection using ssh2 directly.

richard-peters commented 2 years ago

@mscdex - that's fixed the issue. Many thanks, really appreciate your help.

richard-peters commented 2 years ago

@mscdex - should I fork the repo or will this be merged to master?

mscdex commented 2 years ago

@richard-peters It will be merged. I wanted to confirm the fix with @kelly1266 first.

mscdex commented 2 years ago

Thanks for the confirmations.