Timeout on STOR with tls enabled

[jquintozamora]

I'm having issues when trying to upload some files to ftp server when TLS is enabled:

{"name":"ftp-srv","hostname":"laptop","pid":16256,"id":"-8197-4e6d-b1f8-a944121da3d8","directive":"STOR","level":50,"err":{"message":"operation timed out","name":"TimeoutError","stack":"TimeoutError: operation timed out\n    at afterTimeout (/home/jquinto/node_modules/bluebird/js/release/timers.js:46:19)\n    at Timeout.timeoutTimeout [as _onTimeout] (/home/jquinto/node_modules/bluebird/js/release/timers.js:76:13)\n    at ontimeout (timers.js:498:11)\n    at tryOnTimeout (timers.js:323:5)\n    at Timer.listOnTimeout (timers.js:290:5)"},"msg":"operation timed out","time":"2018-06-14T09:14:30.628Z","v":0}

Note: If TLS disabled that works perfectly.

My code:

const server = new FtpServer("ftps://127.0.0.1:8880", {
  logger,
  pasv_range: 8881,
  tls: {
    key: `${process.cwd()}/cert/server.key`,
    cert: `${process.cwd()}/cert/server.crt`,
    ca: `${process.cwd()}/cert/server.csr`
  },
  anonymous: true
})
server.on("login", ({ connection, username, password }, resolve, reject) => {
  if ((username === "test" && password === "test") || username === "anonymous") {
    connection.on("STOR", (error, fileName) => {
      logger.info("file stored: ", fileName)
    })
    connection.on("RETR", (error, filePath) => {
      logger.info("file downloaded: ", filePath)
    })
    resolve({ root: `${process.cwd()}/bdd/mockftp/root` })
  } else reject("Bad username or password")
})
server.on("client-error", ({ error }) => {
  logger.error(error)
})

server.listen().then(() => {
  logger.info("started FTP service.")
})

[trs]

I've also had some issue with using TLS.
You'll have to forgive me, it's my first time implementing it.

I think there's something missing from the command socket and the data socket when it's created using TLS.

[Marcel2508]

I think I have a pretty similar issue here. I have tls enabled, and I'm using passive FTP connection. I can't upload files to the server. I can traverse directories, download files etc, but I can't upload them. I'm running it inside a docker-container with mounted volumes and folders. I double checked permissions etc, and tested it with root user aswell. Sometimes it's working, but sometimes I get the following errors:

{"name":"ftpLogger","hostname":"xxx","pid":8,"id":"0fe2928c-9db1-4521-a806-3c4f0bdf2cd1","level":10,"msg":"[ 'STOR test' ]","time":"2018-07-25T12:23:18.920Z","v":0} ftpfileserver_1 | {"name":"ftpLogger","hostname":"xxx","pid":8,"id":"0fe2928c-9db1-4521-a806-3c4f0bdf2cd1","directive":"STOR","level":10,"command":{"directive":"STOR","arg":"test","flags":[],"raw":"STOR test"},"msg":"Handle command","time":"2018-07-25T12:23:18.920Z","v":0} ftpfileserver_1 | {"name":"ftpLogger","hostname":"xxx","pid":8,"id":"0fe2928c-9db1-4521-a806-3c4f0bdf2cd1","level":10,"port":9001,"remoteAddress":"x.x.x.x","msg":"Passive connection fulfilled.","time":"2018-07-25T12:23:18.952Z","v":0} ftpfileserver_1 | {"name":"ftpLogger","hostname":"xxx","pid":8,"id":"0fe2928c-9db1-4521-a806-3c4f0bdf2cd1","level":10,"msg":"Passive connection closed","time":"2018-07-25T12:23:19.021Z","v":0} ftpfileserver_1 | {"name":"ftpLogger","hostname":"xxx","pid":8,"id":"0fe2928c-9db1-4521-a806-3c4f0bdf2cd1","level":10,"msg":"Passive server closed","time":"2018-07-25T12:23:19.022Z","v":0} ftpfileserver_1 | {"name":"ftpLogger","hostname":"xxx","pid":8,"id":"0fe2928c-9db1-4521-a806-3c4f0bdf2cd1","directive":"STOR","level":50,"err":{"message":"operation timed out","name":"TimeoutError","stack":"TimeoutError: operation timed out\n at afterTimeout (/var/app/node_modules/bluebird/js/release/timers.js:46:19)\n at Timeout.timeoutTimeout [as _onTimeout] (/var/app/node_modules/bluebird/js/release/timers.js:76:13)\n at ontimeout (timers.js:475:11)\n at tryOnTimeout (timers.js:310:5)\n at Timer.listOnTimeout (timers.js:270:5)"},"msg":"operation timed out","time":"2018-07-25T12:23:23.925Z","v":0} ftpfileserver_1 | {"name":"ftpLogger","hostname":"xxx","pid":8,"id":"0fe2928c-9db1-4521-a806-3c4f0bdf2cd1","level":10,"port":9000,"encoding":"utf8","message":"425 No connection established","msg":"Reply","time":"2018-07-25T12:23:23.925Z","v":0}

Im using filezilla (3.15.0.2) on linux
When I disable tls. It seems to work..

I hope someone can get this fixed. I really like this module!

[trs]

This should be fixed in the latest release!

[Marcel2508]

Hmmm. It looks like I'm still getting the same error?
I tried to install it by chaning the version configuration in my "package.json" to 2.19.5, deleting node_modules & ran npm install afterwards
But I'm still getting the same error..
My SSL Configuration looks like this.

tls:{
        key:path.join(__dirname,"tls","private.key"),
        cert:path.join(__dirname,"tls","cert.crt")
}

[trs]

@Marcel2508 Can you post your server config?

[zomas]

@trs Any progress on this? I really need TLS for my implementation and 2.19.5 still has this issue.

[trs]

@zomas Sorry for the slow replies. No new progress on this front as of yet.

[Johnnyrook777]

Im also seeing this issue.

[Johnnyrook777]

#126

[trs]

#128

[trs]

Fixed by v3.0.2 with the help of @Johnnyrook777

[ldm314]

I'm seeing this issue on STOR and RETR with the latest code and passive mode. Strangely enough LIST is working fine. If I copy the logic from the registered commands of LIST into RETR, without TLS on I get a text file with the directory listing as expected and with TLS I see the timeout.

List has PASV before it, makes a new listening connection, has TLS succeed, and sends the directory list across. STOR and RETR have waitForConnection time out in passive.js. With TLS off, no issue. I've tried various node versions: 8,x, 12.x, 15.x with the same result. Wireshark show the client making a connection successfully but TLS negotiation doesn't happen, and eventually waitForConnection times out.

[ldm314]

My app is only using RETR and not STOR. The issue looks like a race condition or a sequencing issue with these commands. I have fixed it for RETR and made a PR: #233

[codezork]

Isn't anybody fixing this issue? We would heavily need this bug fixed.