Rclone copy to FTP: rclone sends a QUIT and never ends itself

Thanks for your help.

I removed concurrency = 1 (I supposed it was here to force only one file at time)

But still some problem.

rclone do not stay infinitely blocked as before

But still the transfer don't works

Here dump-bodies

2021/05/07 21:28:03 NOTICE: --dump-bodies is obsolete - please use --dump bodies instead
2021/05/07 21:28:03 DEBUG : Using config file from "/home/username/.config/rclone/rclone.conf"
2021/05/07 21:28:03 DEBUG : rclone: Version "v1.55.1" starting with parameters ["rclone" "copy" "/home/username/mongo_bckp/customer_availabilities.csv" "customer_ftp:/" "-vv" "--dump-bodies"]
2021/05/07 21:28:03 DEBUG : Creating backend with remote "/home/username/mongo_bckp/customer_availabilities.csv"
2021/05/07 21:28:03 DEBUG : fs cache: adding new entry for parent of "/home/username/mongo_bckp/customer_availabilities.csv", "/home/username/mongo_bckp"
2021/05/07 21:28:03 DEBUG : Creating backend with remote "customer_ftp:/"
2021/05/07 21:28:03 DEBUG : ftp://domain.com:21: Connecting to FTP server
2021/05/07 21:28:03 DEBUG : FTP Rx: "220 ProFTPD Server (ProFTPD) [157.90.126.95]"
2021/05/07 21:28:03 DEBUG : FTP Tx: "AUTH TLS"
2021/05/07 21:28:03 DEBUG : FTP Rx: "234 AUTH TLS successful"
2021/05/07 21:28:03 DEBUG : FTP Tx: "USER <redacted>"
2021/05/07 21:28:03 DEBUG : FTP Rx: "331 Password required for <redacted>"
2021/05/07 21:28:03 DEBUG : FTP Tx: PASS *****
2021/05/07 21:28:06 DEBUG : FTP Rx: "230 User <redacted> logged in"
2021/05/07 21:28:06 DEBUG : FTP Tx: "FEAT"
2021/05/07 21:28:06 DEBUG : FTP Rx: "211-Features:"
2021/05/07 21:28:06 DEBUG : FTP Rx: " AUTH TLS"
2021/05/07 21:28:06 DEBUG : FTP Rx: " CCC"
2021/05/07 21:28:06 DEBUG : FTP Rx: " CLNT"
2021/05/07 21:28:06 DEBUG : FTP Rx: " EPRT"
2021/05/07 21:28:06 DEBUG : FTP Rx: " EPSV"
2021/05/07 21:28:06 DEBUG : FTP Rx: " HOST"
2021/05/07 21:28:06 DEBUG : FTP Rx: " LANG en-US.UTF-8*"
2021/05/07 21:28:06 DEBUG : FTP Rx: " MDTM"
2021/05/07 21:28:06 DEBUG : FTP Rx: " MFF modify;UNIX.group;UNIX.mode;"
2021/05/07 21:28:06 DEBUG : FTP Rx: " MFMT"
2021/05/07 21:28:06 DEBUG : FTP Rx: " MLST modify*;perm*;size*;type*;unique*;UNIX.group*;UNIX.groupname*;UNIX.mode*;UNIX.owner*;UNIX.ownername*;"
2021/05/07 21:28:06 DEBUG : FTP Rx: " PBSZ"
2021/05/07 21:28:06 DEBUG : FTP Rx: " PROT"
2021/05/07 21:28:06 DEBUG : FTP Rx: " REST STREAM"
2021/05/07 21:28:06 DEBUG : FTP Rx: " SIZE"
2021/05/07 21:28:06 DEBUG : FTP Rx: " SSCN"
2021/05/07 21:28:06 DEBUG : FTP Rx: " TVFS"
2021/05/07 21:28:06 DEBUG : FTP Rx: " UTF8"
2021/05/07 21:28:06 DEBUG : FTP Rx: "211 End"
2021/05/07 21:28:06 DEBUG : FTP Tx: "TYPE I"
2021/05/07 21:28:06 DEBUG : FTP Rx: "200 Type set to I"
2021/05/07 21:28:06 DEBUG : FTP Tx: "OPTS UTF8 ON"
2021/05/07 21:28:06 DEBUG : FTP Rx: "200 UTF8 set to on"
2021/05/07 21:28:06 DEBUG : FTP Tx: "PBSZ 0"
2021/05/07 21:28:06 DEBUG : FTP Rx: "200 PBSZ 0 successful"
2021/05/07 21:28:06 DEBUG : FTP Tx: "PROT P"
2021/05/07 21:28:06 DEBUG : FTP Rx: "200 Protection set to Private"
2021/05/07 21:28:06 DEBUG : FTP Tx: "EPSV"
2021/05/07 21:28:06 DEBUG : FTP Rx: "229 Entering Extended Passive Mode (|||62114|)"
2021/05/07 21:28:06 DEBUG : FTP Tx: "MLSD /"
2021/05/07 21:28:06 DEBUG : FTP Rx: "150 Opening BINARY mode data connection for MLSD"
2021/05/07 21:28:06 DEBUG : FTP Rx: "226 Transfer complete"
2021/05/07 21:28:06 DEBUG : customer_availabilities.csv: Need to transfer - File not found at Destination
2021/05/07 21:28:06 DEBUG : FTP Tx: "EPSV"
2021/05/07 21:28:06 DEBUG : FTP Rx: "229 Entering Extended Passive Mode (|||55957|)"
2021/05/07 21:28:06 DEBUG : FTP Tx: "STOR /customer_availabilities.csv"
2021/05/07 21:28:06 DEBUG : FTP Rx: "150 Opening BINARY mode data connection for /customer_availabilities.csv"
2021/05/07 21:28:06 DEBUG : FTP Rx: "450 Transfer aborted. Link to file server lost"
2021/05/07 21:28:06 DEBUG : FTP Tx: "QUIT"
2021/05/07 21:28:07 DEBUG : ftp://domain.com:21: Connecting to FTP server
2021/05/07 21:28:07 DEBUG : FTP Rx: "220 ProFTPD Server (ProFTPD) [157.90.126.95]"
2021/05/07 21:28:07 DEBUG : FTP Tx: "AUTH TLS"
2021/05/07 21:28:07 DEBUG : FTP Rx: "234 AUTH TLS successful"
2021/05/07 21:28:07 DEBUG : FTP Tx: "USER <redacted>"
2021/05/07 21:28:07 DEBUG : FTP Rx: "331 Password required for <redacted>"
2021/05/07 21:28:07 DEBUG : FTP Tx: PASS *****
2021/05/07 21:28:09 DEBUG : FTP Rx: "230 User <redacted> logged in"
2021/05/07 21:28:09 DEBUG : FTP Tx: "FEAT"
2021/05/07 21:28:09 DEBUG : FTP Rx: "211-Features:"
2021/05/07 21:28:09 DEBUG : FTP Rx: " AUTH TLS"
2021/05/07 21:28:09 DEBUG : FTP Rx: " CCC"
2021/05/07 21:28:09 DEBUG : FTP Rx: " CLNT"
2021/05/07 21:28:09 DEBUG : FTP Rx: " EPRT"
2021/05/07 21:28:09 DEBUG : FTP Rx: " EPSV"
2021/05/07 21:28:09 DEBUG : FTP Rx: " HOST"
2021/05/07 21:28:09 DEBUG : FTP Rx: " LANG en-US.UTF-8*"
2021/05/07 21:28:09 DEBUG : FTP Rx: " MDTM"
2021/05/07 21:28:09 DEBUG : FTP Rx: " MFF modify;UNIX.group;UNIX.mode;"
2021/05/07 21:28:09 DEBUG : FTP Rx: " MFMT"
2021/05/07 21:28:09 DEBUG : FTP Rx: " MLST modify*;perm*;size*;type*;unique*;UNIX.group*;UNIX.groupname*;UNIX.mode*;UNIX.owner*;UNIX.ownername*;"
2021/05/07 21:28:09 DEBUG : FTP Rx: " PBSZ"
2021/05/07 21:28:09 DEBUG : FTP Rx: " PROT"
2021/05/07 21:28:09 DEBUG : FTP Rx: " REST STREAM"
2021/05/07 21:28:09 DEBUG : FTP Rx: " SIZE"
2021/05/07 21:28:09 DEBUG : FTP Rx: " SSCN"
2021/05/07 21:28:09 DEBUG : FTP Rx: " TVFS"
2021/05/07 21:28:09 DEBUG : FTP Rx: " UTF8"
2021/05/07 21:28:09 DEBUG : FTP Rx: "211 End"
2021/05/07 21:28:09 DEBUG : FTP Tx: "TYPE I"
2021/05/07 21:28:09 DEBUG : FTP Rx: "200 Type set to I"
2021/05/07 21:28:09 DEBUG : FTP Tx: "OPTS UTF8 ON"
2021/05/07 21:28:09 DEBUG : FTP Rx: "200 UTF8 set to on"
2021/05/07 21:28:09 DEBUG : FTP Tx: "PBSZ 0"
2021/05/07 21:28:09 DEBUG : FTP Rx: "200 PBSZ 0 successful"
2021/05/07 21:28:09 DEBUG : FTP Tx: "PROT P"
2021/05/07 21:28:09 DEBUG : FTP Rx: "200 Protection set to Private"
2021/05/07 21:28:09 DEBUG : FTP Tx: "EPSV"
2021/05/07 21:28:09 DEBUG : FTP Rx: "229 Entering Extended Passive Mode (|||51497|)"
2021/05/07 21:28:09 DEBUG : FTP Tx: "MLSD /"
2021/05/07 21:28:09 DEBUG : FTP Rx: "150 Opening BINARY mode data connection for MLSD"
2021/05/07 21:28:09 DEBUG : FTP Rx: "226 Transfer complete"
2021/05/07 21:28:09 DEBUG : FTP Tx: "DELE /customer_availabilities.csv"
2021/05/07 21:28:09 DEBUG : FTP Rx: "250 DELE command successful"
2021/05/07 21:28:09 DEBUG : customer_availabilities.csv: Removed after failed upload: 450 Transfer aborted. Link to file server lost
2021/05/07 21:28:09 ERROR : customer_availabilities.csv: Failed to copy: update stor: 450 Transfer aborted. Link to file server lost
2021/05/07 21:28:09 ERROR : Attempt 1/3 failed with 1 errors and: update stor: 450 Transfer aborted. Link to file server lost
2021/05/07 21:28:09 DEBUG : FTP Tx: "EPSV"
2021/05/07 21:28:09 DEBUG : FTP Rx: "229 Entering Extended Passive Mode (|||60811|)"
2021/05/07 21:28:09 DEBUG : FTP Tx: "MLSD /"
2021/05/07 21:28:09 DEBUG : FTP Rx: "150 Opening BINARY mode data connection for MLSD"
2021/05/07 21:28:09 DEBUG : FTP Rx: "226 Transfer complete"
2021/05/07 21:28:09 DEBUG : customer_availabilities.csv: Need to transfer - File not found at Destination
2021/05/07 21:28:09 DEBUG : FTP Tx: "EPSV"
2021/05/07 21:28:09 DEBUG : FTP Rx: "229 Entering Extended Passive Mode (|||63628|)"
2021/05/07 21:28:09 DEBUG : FTP Tx: "STOR /customer_availabilities.csv"
2021/05/07 21:28:09 DEBUG : FTP Rx: "150 Opening BINARY mode data connection for /customer_availabilities.csv"
2021/05/07 21:28:09 DEBUG : FTP Rx: "450 Transfer aborted. Link to file server lost"
2021/05/07 21:28:09 DEBUG : FTP Tx: "QUIT"
2021/05/07 21:28:10 DEBUG : ftp://domain.com:21: Connecting to FTP server
2021/05/07 21:28:11 DEBUG : FTP Rx: "220 ProFTPD Server (ProFTPD) [157.90.126.95]"
2021/05/07 21:28:11 DEBUG : FTP Tx: "AUTH TLS"
2021/05/07 21:28:11 DEBUG : FTP Rx: "234 AUTH TLS successful"
2021/05/07 21:28:11 DEBUG : FTP Tx: "USER <redacted>"
2021/05/07 21:28:11 DEBUG : FTP Rx: "331 Password required for <redacted>"
2021/05/07 21:28:11 DEBUG : FTP Tx: PASS *****
2021/05/07 21:28:14 DEBUG : FTP Rx: "230 User <redacted> logged in"
2021/05/07 21:28:14 DEBUG : FTP Tx: "FEAT"
2021/05/07 21:28:14 DEBUG : FTP Rx: "211-Features:"
2021/05/07 21:28:14 DEBUG : FTP Rx: " AUTH TLS"
2021/05/07 21:28:14 DEBUG : FTP Rx: " CCC"
2021/05/07 21:28:14 DEBUG : FTP Rx: " CLNT"
2021/05/07 21:28:14 DEBUG : FTP Rx: " EPRT"
2021/05/07 21:28:14 DEBUG : FTP Rx: " EPSV"
2021/05/07 21:28:14 DEBUG : FTP Rx: " HOST"
2021/05/07 21:28:14 DEBUG : FTP Rx: " LANG en-US.UTF-8*"
2021/05/07 21:28:14 DEBUG : FTP Rx: " MDTM"
2021/05/07 21:28:14 DEBUG : FTP Rx: " MFF modify;UNIX.group;UNIX.mode;"
2021/05/07 21:28:14 DEBUG : FTP Rx: " MFMT"
2021/05/07 21:28:14 DEBUG : FTP Rx: " MLST modify*;perm*;size*;type*;unique*;UNIX.group*;UNIX.groupname*;UNIX.mode*;UNIX.owner*;UNIX.ownername*;"
2021/05/07 21:28:14 DEBUG : FTP Rx: " PBSZ"
2021/05/07 21:28:14 DEBUG : FTP Rx: " PROT"
2021/05/07 21:28:14 DEBUG : FTP Rx: " REST STREAM"
2021/05/07 21:28:14 DEBUG : FTP Rx: " SIZE"
2021/05/07 21:28:14 DEBUG : FTP Rx: " SSCN"
2021/05/07 21:28:14 DEBUG : FTP Rx: " TVFS"
2021/05/07 21:28:14 DEBUG : FTP Rx: " UTF8"
2021/05/07 21:28:14 DEBUG : FTP Rx: "211 End"
2021/05/07 21:28:14 DEBUG : FTP Tx: "TYPE I"
2021/05/07 21:28:14 DEBUG : FTP Rx: "200 Type set to I"
2021/05/07 21:28:14 DEBUG : FTP Tx: "OPTS UTF8 ON"
2021/05/07 21:28:14 DEBUG : FTP Rx: "200 UTF8 set to on"
2021/05/07 21:28:14 DEBUG : FTP Tx: "PBSZ 0"
2021/05/07 21:28:14 DEBUG : FTP Rx: "200 PBSZ 0 successful"
2021/05/07 21:28:14 DEBUG : FTP Tx: "PROT P"
2021/05/07 21:28:14 DEBUG : FTP Rx: "200 Protection set to Private"
2021/05/07 21:28:14 DEBUG : FTP Tx: "EPSV"
2021/05/07 21:28:14 DEBUG : FTP Rx: "229 Entering Extended Passive Mode (|||58715|)"
2021/05/07 21:28:14 DEBUG : FTP Tx: "MLSD /"
2021/05/07 21:28:14 DEBUG : FTP Rx: "150 Opening BINARY mode data connection for MLSD"
2021/05/07 21:28:14 DEBUG : FTP Rx: "226 Transfer complete"
2021/05/07 21:28:14 DEBUG : FTP Tx: "DELE /customer_availabilities.csv"
2021/05/07 21:28:14 DEBUG : FTP Rx: "250 DELE command successful"
2021/05/07 21:28:14 DEBUG : customer_availabilities.csv: Removed after failed upload: 450 Transfer aborted. Link to file server lost
2021/05/07 21:28:14 ERROR : customer_availabilities.csv: Failed to copy: update stor: 450 Transfer aborted. Link to file server lost
2021/05/07 21:28:14 ERROR : Attempt 2/3 failed with 1 errors and: update stor: 450 Transfer aborted. Link to file server lost
2021/05/07 21:28:14 DEBUG : FTP Tx: "EPSV"
2021/05/07 21:28:14 DEBUG : FTP Rx: "229 Entering Extended Passive Mode (|||56450|)"
2021/05/07 21:28:14 DEBUG : FTP Tx: "MLSD /"
2021/05/07 21:28:14 DEBUG : FTP Rx: "150 Opening BINARY mode data connection for MLSD"
2021/05/07 21:28:14 DEBUG : FTP Rx: "226 Transfer complete"
2021/05/07 21:28:14 DEBUG : customer_availabilities.csv: Need to transfer - File not found at Destination
2021/05/07 21:28:14 DEBUG : FTP Tx: "EPSV"
2021/05/07 21:28:14 DEBUG : FTP Rx: "229 Entering Extended Passive Mode (|||65529|)"
2021/05/07 21:28:14 DEBUG : FTP Tx: "STOR /customer_availabilities.csv"
2021/05/07 21:28:14 DEBUG : FTP Rx: "150 Opening BINARY mode data connection for /customer_availabilities.csv"
2021/05/07 21:28:14 DEBUG : FTP Rx: "450 Transfer aborted. Link to file server lost"
2021/05/07 21:28:14 DEBUG : FTP Tx: "QUIT"
2021/05/07 21:28:15 DEBUG : ftp://domain.com:21: Connecting to FTP server
2021/05/07 21:28:15 DEBUG : FTP Rx: "220 ProFTPD Server (ProFTPD) [157.90.126.95]"
2021/05/07 21:28:15 DEBUG : FTP Tx: "AUTH TLS"
2021/05/07 21:28:15 DEBUG : FTP Rx: "234 AUTH TLS successful"
2021/05/07 21:28:15 DEBUG : FTP Tx: "USER <redacted>"
2021/05/07 21:28:15 DEBUG : FTP Rx: "331 Password required for <redacted>"
2021/05/07 21:28:15 DEBUG : FTP Tx: PASS *****
2021/05/07 21:28:17 DEBUG : FTP Rx: "230 User <redacted> logged in"
2021/05/07 21:28:17 DEBUG : FTP Tx: "FEAT"
2021/05/07 21:28:17 DEBUG : FTP Rx: "211-Features:"
2021/05/07 21:28:17 DEBUG : FTP Rx: " AUTH TLS"
2021/05/07 21:28:17 DEBUG : FTP Rx: " CCC"
2021/05/07 21:28:17 DEBUG : FTP Rx: " CLNT"
2021/05/07 21:28:17 DEBUG : FTP Rx: " EPRT"
2021/05/07 21:28:17 DEBUG : FTP Rx: " EPSV"
2021/05/07 21:28:17 DEBUG : FTP Rx: " HOST"
2021/05/07 21:28:17 DEBUG : FTP Rx: " LANG en-US.UTF-8*"
2021/05/07 21:28:17 DEBUG : FTP Rx: " MDTM"
2021/05/07 21:28:17 DEBUG : FTP Rx: " MFF modify;UNIX.group;UNIX.mode;"
2021/05/07 21:28:17 DEBUG : FTP Rx: " MFMT"
2021/05/07 21:28:17 DEBUG : FTP Rx: " MLST modify*;perm*;size*;type*;unique*;UNIX.group*;UNIX.groupname*;UNIX.mode*;UNIX.owner*;UNIX.ownername*;"
2021/05/07 21:28:17 DEBUG : FTP Rx: " PBSZ"
2021/05/07 21:28:17 DEBUG : FTP Rx: " PROT"
2021/05/07 21:28:17 DEBUG : FTP Rx: " REST STREAM"
2021/05/07 21:28:17 DEBUG : FTP Rx: " SIZE"
2021/05/07 21:28:17 DEBUG : FTP Rx: " SSCN"
2021/05/07 21:28:17 DEBUG : FTP Rx: " TVFS"
2021/05/07 21:28:17 DEBUG : FTP Rx: " UTF8"
2021/05/07 21:28:17 DEBUG : FTP Rx: "211 End"
2021/05/07 21:28:17 DEBUG : FTP Tx: "TYPE I"
2021/05/07 21:28:17 DEBUG : FTP Rx: "200 Type set to I"
2021/05/07 21:28:17 DEBUG : FTP Tx: "OPTS UTF8 ON"
2021/05/07 21:28:17 DEBUG : FTP Rx: "200 UTF8 set to on"
2021/05/07 21:28:17 DEBUG : FTP Tx: "PBSZ 0"
2021/05/07 21:28:17 DEBUG : FTP Rx: "200 PBSZ 0 successful"
2021/05/07 21:28:17 DEBUG : FTP Tx: "PROT P"
2021/05/07 21:28:17 DEBUG : FTP Rx: "200 Protection set to Private"
2021/05/07 21:28:17 DEBUG : FTP Tx: "EPSV"
2021/05/07 21:28:17 DEBUG : FTP Rx: "229 Entering Extended Passive Mode (|||59044|)"
2021/05/07 21:28:17 DEBUG : FTP Tx: "MLSD /"
2021/05/07 21:28:17 DEBUG : FTP Rx: "150 Opening BINARY mode data connection for MLSD"
2021/05/07 21:28:17 DEBUG : FTP Rx: "226 Transfer complete"
2021/05/07 21:28:17 DEBUG : FTP Tx: "DELE /customer_availabilities.csv"
2021/05/07 21:28:17 DEBUG : FTP Rx: "250 DELE command successful"
2021/05/07 21:28:17 DEBUG : customer_availabilities.csv: Removed after failed upload: 450 Transfer aborted. Link to file server lost
2021/05/07 21:28:17 ERROR : customer_availabilities.csv: Failed to copy: update stor: 450 Transfer aborted. Link to file server lost
2021/05/07 21:28:17 ERROR : Attempt 3/3 failed with 1 errors and: update stor: 450 Transfer aborted. Link to file server lost
2021/05/07 21:28:17 INFO  :
Transferred:      456.814k / 456.814 kBytes, 100%, 39.626 kBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Elapsed time:        14.2s

2021/05/07 21:28:17 DEBUG : 3 go routines active
2021/05/07 21:28:17 Failed to copy: update stor: 450 Transfer aborted. Link to file server lost

I tried adding --ftp-disable-mlsd but nothing changes

I triead also adding --ftp-disable-epsv but nothing changes

I tried --no-check-dest but nothing changes

But WHY rclone is deleting file ?!?!

This is the underlying problem.

Not sure what is causing that.

The server is proftpd isn't it which shouldn't be a problem - we test against that daily.

I wonder if it is the TLS causing the problem.

Can you try without?

Rclone deletes the partial file because the transfer failed.

I have the exact same issue as OP

Using FTP without TLS works without any problems, so it looks like it is something TLS related. As soon as I enable TLS it will start the transfer of the first few files (specified with the ftp-concurrency parameter), but the transfer goes to 100% and freezes. It's like rclone cannot "finish" the transfer.

Edit:
After rclone transfered 24/30 files it stopped again at 100%.

That is good to know.

Can you try the latest beta and see if that fixes it - there were some ftp backend changes in there

Also did you turn off session resumption

I think this may be related to this issue FTPS (FTP with implicit TLS) issues in rclone-v1.55.0-windows-amd64 · Issue #5210 · rclone/rclone · GitHub which should be fixed in 1.55.1 but maybe something went wrong with the backport.

I see this problem with hetzner storage box.
tl;dr The bug was introduced between rclone 1.53 and 1.55

config section:

[stobox-ftp]
type = ftp
host = XXX.your-storagebox.de
user = XXX
pass = XXX
explicit_tls = true

[stobox-sftp]
type = sftp
host = XXX.your-storagebox.de
user = XXX
pass = XXX

SFTP works fine:

rclone copy ./file_60mb.bin stobox-sftp:

FTP with explicit TLS fails for me:

rclone copy ./file_60mb.bin stobox-ftp:

I did not try pure FTP for security. According to reports above it should work fine.

Failure log with verbose dump:

2021/06/04 21:53:42 DEBUG : rclone: Version "v1.56.0-DEV" starting with parameters ["rclone" "copy" "-P" "60m" "stobox:" "--dump" "headers,bodies,auth" "-vv"]
2021/06/04 21:53:42 DEBUG : Creating backend with remote "60m"
2021/06/04 21:53:42 DEBUG : Using config file from "/home/XXX/.rclone.conf"
2021/06/04 21:53:42 DEBUG : fs cache: adding new entry for parent of "60m", "/home/XXX"
2021/06/04 21:53:42 DEBUG : Creating backend with remote "stobox:"
2021/06/04 21:53:42 DEBUG : ftp://XXX.your-storagebox.de:21: Connecting to FTP server
2021/06/04 21:53:42 DEBUG : FTP Rx: "220 ProFTPD Server (Hetzner Backup) [XXX]"
2021/06/04 21:53:42 DEBUG : FTP Tx: "AUTH TLS"
2021/06/04 21:53:42 DEBUG : FTP Rx: "234 AUTH TLS successful"
2021/06/04 21:53:42 DEBUG : FTP Tx: "USER XXX"
2021/06/04 21:53:42 DEBUG : FTP Rx: "331 Password required for XXX"
2021/06/04 21:53:42 DEBUG : FTP Tx: "PASS XXX"
2021/06/04 21:53:42 DEBUG : FTP Rx: "230 User XXX logged in"
2021/06/04 21:53:42 DEBUG : FTP Tx: "FEAT"
2021/06/04 21:53:42 DEBUG : FTP Rx: "211-Features:"
2021/06/04 21:53:42 DEBUG : FTP Rx: " AUTH TLS"
2021/06/04 21:53:42 DEBUG : FTP Rx: " CCC"
2021/06/04 21:53:42 DEBUG : FTP Rx: " CLNT"
2021/06/04 21:53:42 DEBUG : FTP Rx: " EPRT"
2021/06/04 21:53:42 DEBUG : FTP Rx: " EPSV"
2021/06/04 21:53:42 DEBUG : FTP Rx: " HOST"
2021/06/04 21:53:42 DEBUG : FTP Rx: " LANG ko-KR.UTF-8;ko-KR;it-IT.UTF-8;it-IT;es-ES.UTF-8;es-ES;bg-BG.UTF-8;bg-BG;ru-RU.UTF-8;ru-RU;zh-TW.UTF-8;zh-TW;zh-CN.UTF-8;zh-CN;ja-JP;fr-FR.UTF-8;fr-FR;en-US.UTF-8;en-US*"
2021/06/04 21:53:42 DEBUG : FTP Rx: " MDTM"
2021/06/04 21:53:42 DEBUG : FTP Rx: " MFF modify;UNIX.group;UNIX.mode;"
2021/06/04 21:53:42 DEBUG : FTP Rx: " MFMT"
2021/06/04 21:53:42 DEBUG : FTP Rx: " MLST modify*;perm*;size*;type*;unique*;UNIX.group*;UNIX.groupname*;UNIX.mode*;UNIX.owner*;UNIX.ownername*;"
2021/06/04 21:53:42 DEBUG : FTP Rx: " PBSZ"
2021/06/04 21:53:42 DEBUG : FTP Rx: " PROT"
2021/06/04 21:53:42 DEBUG : FTP Rx: " RANG STREAM"
2021/06/04 21:53:42 DEBUG : FTP Rx: " REST STREAM"
2021/06/04 21:53:42 DEBUG : FTP Rx: " SIZE"
2021/06/04 21:53:42 DEBUG : FTP Rx: " SSCN"
2021/06/04 21:53:42 DEBUG : FTP Rx: " TVFS"
2021/06/04 21:53:42 DEBUG : FTP Rx: " UTF8"
2021/06/04 21:53:42 DEBUG : FTP Rx: "211 End"
2021/06/04 21:53:42 DEBUG : FTP Tx: "TYPE I"
2021/06/04 21:53:42 DEBUG : FTP Rx: "200 Type set to I"
2021/06/04 21:53:42 DEBUG : FTP Tx: "OPTS UTF8 ON"
2021/06/04 21:53:42 DEBUG : FTP Rx: "200 UTF8 set to on"
2021/06/04 21:53:42 DEBUG : FTP Tx: "PBSZ 0"
2021/06/04 21:53:42 DEBUG : FTP Rx: "200 PBSZ 0 successful"
2021/06/04 21:53:42 DEBUG : FTP Tx: "PROT P"
2021/06/04 21:53:42 DEBUG : FTP Rx: "200 Protection set to Private"
2021-06-04 21:53:42 DEBUG : FTP Tx: "EPSV"
2021-06-04 21:53:42 DEBUG : FTP Rx: "229 Entering Extended Passive Mode (|||49152|)"
2021-06-04 21:53:42 DEBUG : FTP Tx: "MLSD ."
2021-06-04 21:53:42 DEBUG : FTP Rx: "150 Opening BINARY mode data connection for MLSD"
2021-06-04 21:53:42 DEBUG : FTP Rx: "226 Transfer complete"
2021-06-04 21:53:42 DEBUG : 60m: Need to transfer - File not found at Destination
2021-06-04 21:53:42 DEBUG : FTP Tx: "EPSV"
2021-06-04 21:53:42 DEBUG : FTP Rx: "229 Entering Extended Passive Mode (|||53461|)"
2021-06-04 21:53:42 DEBUG : FTP Tx: "MLSD ."
2021-06-04 21:53:42 DEBUG : FTP Rx: "150 Opening BINARY mode data connection for MLSD"
2021-06-04 21:53:42 DEBUG : FTP Rx: "226 Transfer complete"
2021-06-04 21:53:42 DEBUG : FTP Tx: "EPSV"
2021-06-04 21:53:42 DEBUG : FTP Rx: "229 Entering Extended Passive Mode (|||57526|)"
2021-06-04 21:53:42 DEBUG : FTP Tx: "MLSD ."
2021-06-04 21:53:42 DEBUG : FTP Rx: "150 Opening BINARY mode data connection for MLSD"
2021-06-04 21:53:42 DEBUG : FTP Rx: "226 Transfer complete"
2021-06-04 21:53:42 DEBUG : FTP Tx: "EPSV"
2021-06-04 21:53:42 DEBUG : FTP Rx: "229 Entering Extended Passive Mode (|||64179|)"
2021-06-04 21:53:42 DEBUG : FTP Tx: "STOR 60m"
2021-06-04 21:53:42 DEBUG : FTP Rx: "150 Opening BINARY mode data connection for 60m"
2021-06-04 21:53:44 DEBUG : FTP Rx: "450 Transfer aborted. Link to file server lost"
2021-06-04 21:53:44 DEBUG : FTP Tx: "QUIT"

Final error message:

Failed to copy: update stor: 450 Transfer aborted. Link to file server lost

Failing rclone versions: 1.55.1, git master

However rclone version 1.52.3 works fine.

I did not try other versions in between.
Will do git bisect later.

Bisection pointed me to the first patch introducing support for FTP's explicit_tls in rclone. In fact 1.52.3 did not recognize the explicit_tls parameter, ignored it and accessed FTP by plain protocol. Thus, the explicit_tls mode always had the problem in question.

Surfing through the github threads related to the FTP TLS bugs, I stumbled upon this comment: Failing data connection with STARTTLS (Explicit TLS): tls session not reused · Issue #49 · secsy/goftp · GitHub

I then made a patch adding tls session cache in the ftp backend: Commits · ivandeex/rclone · GitHub
Running rclone with tls cache enabled fixed the upload to hetzner storage for me. This is nice because FTP+TLS gives me the 80MB/s upload speed while workaround with SFTP capped at 40MB/s, both being securely encryped.

FWIW Please try rclone beta with the patch from Release v1.55.1-ftp02 · ivandeex/rclone · GitHub
Note that I don't fully understand all security implications of tls session cache or how big it should be, so by default it's disabled. To enable it and fix the 450 problem, you should enable it manually via command line flag --ftp-tls-cache-size=64, or add the line tls_cache_size = 64 in the ftp section of rclone.conf

Please let me know if it helped you. Maybe it deserves submitting a patch for the mainline rclone.

I tested the TLS session cache a little more with hetzner storage box using a 4GB file. While uploads seem to be fixed, downloads are broken. In the middle of download rclone resets the stream back, then downloads again and again, forever.
Please don't use the above beta for real data. I don't have much time to continue with the patch. My real storage will use SFTP.

Nice one :slight_smile:

:frowning: Is this a timeout?

I don't know. Feels broken. I stopped this experiment and reverted to SFTP.

1 Like

Hi, I have the exact same problem. I try to transfer a directory of small files, but files over certain size aren't transferred, no matter how many times I try.
The largest file sent successfully is 6.11 kB,
The smallest file with error is 17.3 kB,
so the threshold is somewhere in between,

ivandeex, the links to the patch in your post do not work (404), so I don't know how to try it.
Tried the latest beta (1.56.0-beta.5589), but the patch doesn't seem to be merged yet (doesn't recognize the --ftp-tls-cache-size=64 flag).

I din't submit the patch and removed the beta build. Will investigate further.

Currently you can try this dev build

of this dev branch

I was able to correctly download a 2g file from hetzner storage box via ftp+explicit tls, handwaving harmless error messages about close timeouts, though the speed (9 Mib/s) sucks vs sftp (30 Mib/s) or pure ftp (100 Mib/s). note: rclone and storage box live in two germany hetzner datacenters.

config:

type = ftp
host = u123456.your-storagebox.de
user = u123456
pass = s123456
encoding = Slash,Asterisk,Ctl,Dot
explicit_tls = true
no_check_certificate = true
close_timeout = 0
data_close_timeout = 1m

build:

The key problem with hetzner storage box (ProFTPd v1.3.something on FreeBSD) likely stems from incorrect use of timeouts by rclone and the jlaffaye/ftp library. Timeout related bugs reveal with large files both in plain and in tls modes.

problematic spots in code:

cc @ncw

Thank you, but it doesn't help in my case. Still the same behaviour. I tried increasing the cache size to 256, but still the same.

I think I will switch to SFTP in the end, because it supports modtime and hashes. But have to resolve other problems I have with it first.

Looks like I cannot use SFTP, and have to stick to FTPS.
In the previous test I forgot to set disable_tls13. After set to true, the transfer works, but now I'm getting some weird FTP error, that is most likely unrelated to rclone (but perhaps someone knows what may be causing it?):

2021/07/19 16:40:46 DEBUG : FTP Tx: "MFMT 20060918115312 /test_rclone/current/Test.zip"
2021/07/19 16:40:46 DEBUG : FTP Rx: "501 /test_rclone/current/Test.zip: Operation not permitted"
2021/07/19 16:40:46 ERROR : Test.zip: Failed to copy: SetModTime: 501 /test_rclone/current/Test.zip: Operation not permitted

The server is ProFTPD with RPi OS, and NTFS drive attached.
I tried setting writing_mdtm to true, as the description says "Use MDTM to set modification time (non-standard)" (which is strange, because according to Wikipedia, MDTM is used to read modification time, not set it). But enabling it didn't change anything, and rclone still used MFMT.

on my experimental branch rclone will issue the MFMT/MDTM optional command to set file time as soon as ftp server adverises it.
the mainline doesn't support this feature yet.
looks like your server advertises it but prohibits afterwards, but i'm not sure.
could you run your command with -vv --log-file log --dump bodies and attach the log below?

rfc standardizes something.
wikipedia writes something else.
then come vsftpd developers and name the set file time command as MDTM time path.
therefore i added it as optional, enabled only by flag.

authors of ftp servers are strange folks, you can send them the link to wikipedia. dont ask me.

btw here is my config for hetzner sftp, it works fine for me

[sbsftp]
type = sftp
host = u123456.your-storagebox.de
user = u123456
pass = heil-hetzner
md5sum_command = none
sha1sum_command = none

Here is my log. Thanks.
rclone.log (42.4 KB)

Shouldn't rclone respect --no-update-modtime flag? I have the flag, but rclone tries to update the modtime anyway.

That's for if files are identical:

 --no-update-modtime                    Don't update destination mod-time if files identical.

With a new copy, it will update the mod time.