ssh2-streams icon indicating copy to clipboard operation
ssh2-streams copied to clipboard
verified publisher icon mscdex

Error when streaming 'large' files

Open mathiastj opened this issue 8 years ago • 6 comments

Hi there

I'm trying to use createWriteStream to transfer files from my client to a server. When the files are bigger than 4-5MB the transfer stops at some point and hangs and then either ECONNRESET or ETIMEDOUT errors occur. If the files are smaller they are usually transferred without problems.

The server is running SSH-2.0-CompleteFTP_10.2.1

Here is a log detailing the events:

DEBUG: Local ident: 'SSH-2.0-ssh2js0.1.20'
DEBUG: Client: Trying HOST_IP on port 22 ...
DEBUG: Client: Connected
DEBUG: Parser: IN_INIT
DEBUG: Parser: IN_GREETING
DEBUG: Parser: IN_HEADER
DEBUG: Remote ident: 'SSH-2.0-CompleteFTP_10.2.1'
DEBUG: Outgoing: Writing KEXINIT
DEBUG: Parser: IN_PACKETBEFORE (expecting 8)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: pktLen:548,padLen:10,remainLen:544
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: IN_PACKETDATAAFTER, packet: KEXINIT
DEBUG: Comparing KEXINITs ...
DEBUG: (local) KEX algorithms: ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group14-sha1
DEBUG: (remote) KEX algorithms: diffie-hellman-group1-sha1,diffie-hellman-group14-sha1,diffie-hellman-group-exchange-sha1,diffie-hellman-group-exchange-sha256
DEBUG: KEX algorithm: diffie-hellman-group-exchange-sha256
DEBUG: (local) Host key formats: ssh-rsa,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521
DEBUG: (remote) Host key formats: ssh-dss,ssh-rsa
DEBUG: Host key format: ssh-rsa
DEBUG: (local) Client->Server ciphers: aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm,[email protected],aes256-gcm,[email protected]
DEBUG: (remote) Client->Server ciphers: blowfish-cbc,3des-cbc,aes128-cbc,aes192-cbc,aes256-cbc,aes128-ctr,aes192-ctr,aes256-ctr
DEBUG: Client->Server Cipher: aes128-ctr
DEBUG: (local) Server->Client ciphers: aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm,[email protected],aes256-gcm,[email protected]
DEBUG: (remote) Server->Client ciphers: blowfish-cbc,3des-cbc,aes128-cbc,aes192-cbc,aes256-cbc,aes128-ctr,aes192-ctr,aes256-ctr
DEBUG: Server->Client Cipher: aes128-ctr
DEBUG: (local) Client->Server HMAC algorithms: hmac-sha2-256,hmac-sha2-512,hmac-sha1
DEBUG: (remote) Client->Server HMAC algorithms: hmac-md5,hmac-md5-96,hmac-sha1,hmac-sha1-96,hmac-sha2-256,hmac-sha2-512
DEBUG: Client->Server HMAC algorithm: hmac-sha2-256
DEBUG: (local) Server->Client HMAC algorithms: hmac-sha2-256,hmac-sha2-512,hmac-sha1
DEBUG: (remote) Server->Client HMAC algorithms: hmac-md5,hmac-md5-96,hmac-sha1,hmac-sha1-96,hmac-sha2-256,hmac-sha2-512
DEBUG: Server->Client HMAC algorithm: hmac-sha2-256
DEBUG: (local) Client->Server compression algorithms: none,[email protected],zlib
DEBUG: (remote) Client->Server compression algorithms: none,zlib
DEBUG: Client->Server compression algorithm: none
DEBUG: (local) Server->Client compression algorithms: none,[email protected],zlib
DEBUG: (remote) Server->Client compression algorithms: none,zlib
DEBUG: Server->Client compression algorithm: none
DEBUG: Outgoing: Writing KEXDH_GEX_REQUEST
DEBUG: Parser: IN_PACKETBEFORE (expecting 8)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: pktLen:532,padLen:8,remainLen:528
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: IN_PACKETDATAAFTER, packet: KEXDH_GEX_GROUP
DEBUG: Outgoing: Writing KEXDH_GEX_INIT
DEBUG: Parser: IN_PACKETBEFORE (expecting 8)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: pktLen:1084,padLen:11,remainLen:1080
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: IN_PACKETDATAAFTER, packet: KEXDH_GEX_REPLY
DEBUG: Checking host key format
DEBUG: Checking signature format
DEBUG: Verifying host fingerprint
DEBUG: Host accepted by default (no verification)
DEBUG: Verifying signature
DEBUG: Outgoing: Writing NEWKEYS
DEBUG: Parser: IN_PACKETBEFORE (expecting 8)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: pktLen:12,padLen:10,remainLen:8
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: IN_PACKETDATAAFTER, packet: NEWKEYS
DEBUG: Outgoing: Writing SERVICE_REQUEST (ssh-userauth)
DEBUG: Parser: IN_PACKETBEFORE (expecting 16)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: Decrypting
DEBUG: Parser: pktLen:28,padLen:10,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: SERVICE_ACCEPT
DEBUG: Outgoing: Writing USERAUTH_REQUEST (none)
DEBUG: Parser: IN_PACKETBEFORE (expecting 16)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: Decrypting
DEBUG: Parser: pktLen:44,padLen:19,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: USERAUTH_FAILURE
DEBUG: Client: none auth failed
DEBUG: Outgoing: Writing USERAUTH_REQUEST (password)
DEBUG: Parser: IN_PACKETBEFORE (expecting 16)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: Decrypting
DEBUG: Parser: pktLen:12,padLen:10,remainLen:0
DEBUG: Parser: IN_PACKETDATA
DEBUG: Parser: HMAC size:32
DEBUG: Parser: IN_PACKETDATAVERIFY
DEBUG: Parser: Verifying MAC
DEBUG: Parser: IN_PACKETDATAVERIFY (Valid HMAC)
DEBUG: Parser: IN_PACKETDATAAFTER, packet: USERAUTH_SUCCESS
Client :: ready
DEBUG: Outgoing: Writing CHANNEL_OPEN (0, session)
DEBUG: Parser: IN_PACKETBEFORE (expecting 16)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: Decrypting
DEBUG: Parser: pktLen:28,padLen:10,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_OPEN_CONFIRMATION
DEBUG: Outgoing: Writing CHANNEL_REQUEST (0, subsystem: sftp)
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, 27)
DEBUG: Parser: IN_PACKETBEFORE (expecting 16)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: Decrypting
DEBUG: Parser: pktLen:12,padLen:6,remainLen:0
DEBUG: Parser: IN_PACKETDATA
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_SUCCESS (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:9,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_DATA (0)
DEBUG: Parser: IN_PACKETBEFORE (expecting 16)
DEBUG[SFTP]: Outgoing: Writing OPEN
DEBUG: Outgoing: Writing CHANNEL_DATA (0)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: Decrypting
DEBUG: Parser: pktLen:44,padLen:11,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:13,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: Parser: IN_PACKETBEFORE (expecting 16)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: Decrypting
DEBUG: Parser: pktLen:44,padLen:13,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: Parser: IN_PACKETBEFORE (expecting 16)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: Decrypting
DEBUG: Parser: pktLen:44,padLen:13,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: Parser: IN_PACKETBEFORE (expecting 16)
DEBUG: Parser: IN_PACKET
DEBUG: Parser: Decrypting
DEBUG: Parser: pktLen:44,padLen:13,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: Parser: IN_PACKETBEFORE (expecting 16)

null: Error: read ETIMEDOUT
DEBUG: Outgoing: Writing CHANNEL_CLOSE (0)

Here is a WireShark trace, showing multiple Malformed Packet https://pastebin.com/k00H1PPF

Here is a minimal working example of the code

this.conn = new Client()
      this.conn
        .on('ready', () => {
          console.log('Client :: ready')
          this.conn.sftp((err, sftp) => {
            if (err) {
              throw err
            }
            const testImport2 = 'test_assets/testfile'
            const fileStream = fs.createReadStream(testImport2)
            let writeStream = sftp.createWriteStream('file.txt')

            writeStream.on('error', err => {
              console.error(err)
              throw err
            })
            writeStream.on('close', async () => {
              console.log('success')
            })

            fileStream.pipe(writeStream)
          })
        })
        .on('error', e => {
          console.log(e)
          throw e
        })
        .connect({
          host: 'HOST_IP',
          username: 'username',
          password: 'password',
          port: 22,
          debug: console.log
        })

I can successfully send big files to my own local sftp server.

mathiastj avatar Feb 02 '18 13:02 mathiastj

Does sftp.fastPut() work better?

mscdex avatar Feb 02 '18 14:02 mscdex

@mscdex is it a different code path?

We are streaming the file directly from a database so we would very much like to use the streaming api instead of having to buffer the file to disk first.

tlbdk avatar Feb 05 '18 08:02 tlbdk

Regardless of our use case, it does indeed work with sftp.fastPut()

mathiastj avatar Feb 05 '18 08:02 mathiastj

@tlbdk Yes, different code.

mscdex avatar Feb 05 '18 08:02 mscdex

I suspect there is something wrong with flow control. sftp stream emits "continue" rather than "drain" on writeData() === false, and WriteStream.prototype._write never checks return value of writeData. Probably both could be fixed with change to WriteStream (on continue emit drain and ~wait for continue/drain~ return false in _write() iff writeData returns false) but a lot of other code is fairly low-level in this package so don't know if I trust myself with a PR.

shaunc avatar Jun 16 '18 03:06 shaunc

I am having issues with large files too. Nothing as small as 4-5mb, but more like files that are in the 5-10GB range. The error message is vague, and doesn't make much sense. Wondering if it has to do with the sftp provider and possibly poor error handling.

{"level":50,"time":1530048066972,"msg":"No such file","pid":33, "type":"Error","stack":"Error: No such file
    at SFTPStream._transform (/home/vcap/app/node_modules/ssh2-streams/lib/sftp.js:412:27)
    at SFTPStream.Transform._read (_stream_transform.js:190:10)
    at SFTPStream._read (/home/vcap/app/node_modules/ssh2-streams/lib/sftp.js:183:15)
    at SFTPStream.Transform._write (_stream_transform.js:178:12)
    at doWrite (_stream_writable.js:410:12)\n    at writeOrBuffer (_stream_writable.js:394:5)
    at SFTPStream.Writable.write (_stream_writable.js:294:11)
    at Channel.ondata (_stream_readable.js:663:20)
    at Channel.emit (events.js:182:13)
    at Channel.EventEmitter.emit (domain.js:442:20)","code":2,"lang":"en","v":1}

jjosef avatar Jun 27 '18 12:06 jjosef