Rclone FTPS (Explicit) + copy -> Failed to copy: update stor: 450 Transfer aborted. Link to file server lost

Hello Rclone Community!

What is the problem you are having with rclone?

I have created an Rclone FTPS (explicit mode) connection to another server.
When trying to transfer files from the source server to the destination server, the file transfer very often ends with an error message:

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

There are cases, where it works, but in most cases, the error is thrown.

Unsecured FTP transfer works like a charm.
Various other Rclone storage configs work like a charm.

What is your rclone version (output from rclone version)

rclone v1.55.1
- os/type: linux
- os/arch: amd64
- go/version: go1.16.3
- go/linking: static
- go/tags: none

I have also tested the latest Beta (v1.56.0-beta.5531.41f561bf2), but without success.

Which OS you are using and how many bits (eg Windows 7, 64 bit)

Ubuntu 18.04 - 64 bit

Which cloud storage system are you using? (eg Google Drive)

FTPS in explicit mode.

The command you were trying to run (eg rclone copy /tmp remote:tmp)

rclone --retries 1 -vv copy /home/users/alex/www/godot-3.3.1-stable.zip rclone-storage:/files/alex/www

The rclone config contents with secrets removed.

I have tried with "no_check_certificate = false" and "no_check_certificate = true". But the results remains the same.

[rclone-storage]
type = ftp
host = dev14.keymachine.de
user = backup_test
pass = <secret_password>
explicit_tls = true
no_check_certificate = false
[rclone-storage]
type = ftp
host = dev14.keymachine.de
user = backup_test
pass = <secret_password>
explicit_tls = true
no_check_certificate = true

A log from the command with the -vv flag

2021/06/07 16:33:25 DEBUG : Using config file from "/root/.config/rclone/rclone.conf"
2021/06/07 16:33:25 DEBUG : rclone: Version "v1.55.1" starting with parameters ["rclone" "--retries" "1" "-vv" "copy" "/home/users/alex/www/godot-3.3.1-stable.zip" "rclone-storage:/files/alex/www"]
2021/06/07 16:33:25 DEBUG : Creating backend with remote "/home/users/alex/www/godot-3.3.1-stable.zip"
2021/06/07 16:33:25 DEBUG : fs cache: adding new entry for parent of "/home/users/alex/www/godot-3.3.1-stable.zip", "/home/users/alex/www"
2021/06/07 16:33:25 DEBUG : Creating backend with remote "rclone-storage:/files/alex/www"
2021/06/07 16:33:25 DEBUG : ftp://dev14.keymachine.de:21/files/alex/www: Connecting to FTP server
2021/06/07 16:33:25 DEBUG : godot-3.3.1-stable.zip: Need to transfer - File not found at Destination
2021/06/07 16:33:27 DEBUG : ftp://dev14.keymachine.de:21/files/alex/www: Connecting to FTP server
2021/06/07 16:33:27 DEBUG : godot-3.3.1-stable.zip: Removed after failed upload: 450 Transfer aborted. Link to file server lost
2021/06/07 16:33:27 ERROR : godot-3.3.1-stable.zip: Failed to copy: update stor: 450 Transfer aborted. Link to file server lost
2021/06/07 16:33:27 ERROR : Attempt 1/1 failed with 1 errors and: update stor: 450 Transfer aborted. Link to file server lost
2021/06/07 16:33:27 INFO  : 
Transferred:   	   33.692M / 33.692 MBytes, 100%, 15.539 MBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Elapsed time:         2.5s

2021/06/07 16:33:27 DEBUG : 2 go routines active
2021/06/07 16:33:27 Failed to copy: update stor: 450 Transfer aborted. Link to file server lost

A log from the command with the --dump bodies -vv flag

2021/06/07 16:20:18 DEBUG : Using config file from "/root/.config/rclone/rclone.conf"
2021/06/07 16:20:18 DEBUG : rclone: Version "v1.55.1" starting with parameters ["rclone" "--dump" "bodies" "--retries" "1" "-vv" "copy" "/home/users/alex/www/godot-3.3.1-stable.zip" "rclone-storage:/files/alex/www"]
2021/06/07 16:20:18 DEBUG : Creating backend with remote "/home/users/alex/www/godot-3.3.1-stable.zip"
2021/06/07 16:20:18 DEBUG : fs cache: adding new entry for parent of "/home/users/alex/www/godot-3.3.1-stable.zip", "/home/users/alex/www"
2021/06/07 16:20:18 DEBUG : Creating backend with remote "rclone-storage:/files/alex/www"
2021/06/07 16:20:18 DEBUG : ftp://dev14.keymachine.de:21/files/alex/www: Connecting to FTP server
2021/06/07 16:20:18 DEBUG : FTP Rx: "220 ProFTPD Server (dev14.keymachine.de FTP-Server) [::ffff:62.141.57.77]"
2021/06/07 16:20:18 DEBUG : FTP Tx: "AUTH TLS"
2021/06/07 16:20:18 DEBUG : FTP Rx: "234 AUTH TLS successful"
2021/06/07 16:20:18 DEBUG : FTP Tx: "USER backup_test"
2021/06/07 16:20:18 DEBUG : FTP Rx: "331 Password required for backup_test"
2021/06/07 16:20:18 DEBUG : FTP Tx: PASS *****
2021/06/07 16:20:18 DEBUG : FTP Rx: "230 User backup_test logged in"
2021/06/07 16:20:18 DEBUG : FTP Tx: "FEAT"
2021/06/07 16:20:18 DEBUG : FTP Rx: "211-Features:"
2021/06/07 16:20:18 DEBUG : FTP Rx: "211-AUTH TLS"
2021/06/07 16:20:18 DEBUG : FTP Rx: "211-CCC"
2021/06/07 16:20:18 DEBUG : FTP Rx: "211-CLNT"
2021/06/07 16:20:18 DEBUG : FTP Rx: "211-EPRT"
2021/06/07 16:20:18 DEBUG : FTP Rx: "211-EPSV"
2021/06/07 16:20:18 DEBUG : FTP Rx: "211-HOST"
2021/06/07 16:20:18 DEBUG : FTP Rx: "211-LANG en-US.UTF-8;en-US"
2021/06/07 16:20:18 DEBUG : FTP Rx: "211-MDTM"
2021/06/07 16:20:18 DEBUG : FTP Rx: "211-MFF modify;UNIX.group;UNIX.mode;"
2021/06/07 16:20:18 DEBUG : FTP Rx: "211-MFMT"
2021/06/07 16:20:18 DEBUG : FTP Rx: "211-MLST modify*;perm*;size*;type*;unique*;UNIX.group*;UNIX.groupname*;UNIX.mode*;UNIX.owner*;UNIX.ownername*;"
2021/06/07 16:20:18 DEBUG : FTP Rx: "211-PBSZ"
2021/06/07 16:20:18 DEBUG : FTP Rx: "211-PROT"
2021/06/07 16:20:18 DEBUG : FTP Rx: "211-REST STREAM"
2021/06/07 16:20:18 DEBUG : FTP Rx: "211-SITE MKDIR"
2021/06/07 16:20:18 DEBUG : FTP Rx: "211-SITE RMDIR"
2021/06/07 16:20:18 DEBUG : FTP Rx: "211-SITE SYMLINK"
2021/06/07 16:20:18 DEBUG : FTP Rx: "211-SITE UTIME"
2021/06/07 16:20:18 DEBUG : FTP Rx: "211-SIZE"
2021/06/07 16:20:18 DEBUG : FTP Rx: "211-SSCN"
2021/06/07 16:20:18 DEBUG : FTP Rx: "211-TVFS"
2021/06/07 16:20:18 DEBUG : FTP Rx: "211-UTF8"
2021/06/07 16:20:18 DEBUG : FTP Rx: "211 End"
2021/06/07 16:20:18 DEBUG : FTP Tx: "TYPE I"
2021/06/07 16:20:18 DEBUG : FTP Rx: "200 Type set to I"
2021/06/07 16:20:18 DEBUG : FTP Tx: "PBSZ 0"
2021/06/07 16:20:18 DEBUG : FTP Rx: "200 PBSZ 0 successful"
2021/06/07 16:20:18 DEBUG : FTP Tx: "PROT P"
2021/06/07 16:20:18 DEBUG : FTP Rx: "200 Protection set to Private"
2021/06/07 16:20:18 DEBUG : FTP Tx: "EPSV"
2021/06/07 16:20:18 DEBUG : FTP Rx: "229 Entering Extended Passive Mode (|||30019|)"
2021/06/07 16:20:18 DEBUG : FTP Tx: "LIST /files/alex"
2021/06/07 16:20:18 DEBUG : FTP Rx: "150 Opening BINARY mode data connection for file list"
2021/06/07 16:20:18 DEBUG : FTP Rx: "226 Transfer complete"
2021/06/07 16:20:18 DEBUG : FTP Tx: "EPSV"
2021/06/07 16:20:18 DEBUG : FTP Rx: "229 Entering Extended Passive Mode (|||30118|)"
2021/06/07 16:20:18 DEBUG : FTP Tx: "LIST /files/alex/www"
2021/06/07 16:20:18 DEBUG : FTP Rx: "150 Opening BINARY mode data connection for file list"
2021/06/07 16:20:18 DEBUG : FTP Rx: "226 Transfer complete"
2021/06/07 16:20:18 DEBUG : godot-3.3.1-stable.zip: Need to transfer - File not found at Destination
2021/06/07 16:20:18 DEBUG : FTP Tx: "EPSV"
2021/06/07 16:20:18 DEBUG : FTP Rx: "229 Entering Extended Passive Mode (|||30283|)"
2021/06/07 16:20:18 DEBUG : FTP Tx: "LIST /files/alex"
2021/06/07 16:20:18 DEBUG : FTP Rx: "150 Opening BINARY mode data connection for file list"
2021/06/07 16:20:18 DEBUG : FTP Rx: "226 Transfer complete"
2021/06/07 16:20:18 DEBUG : FTP Tx: "EPSV"
2021/06/07 16:20:18 DEBUG : FTP Rx: "229 Entering Extended Passive Mode (|||30372|)"
2021/06/07 16:20:18 DEBUG : FTP Tx: "STOR /files/alex/www/godot-3.3.1-stable.zip"
2021/06/07 16:20:18 DEBUG : FTP Rx: "150 Opening BINARY mode data connection for /files/alex/www/godot-3.3.1-stable.zip"
2021/06/07 16:20:19 DEBUG : FTP Rx: "450 Transfer aborted. Link to file server lost"
2021/06/07 16:20:19 DEBUG : FTP Tx: "QUIT"
2021/06/07 16:20:20 DEBUG : ftp://dev14.keymachine.de:21/files/alex/www: Connecting to FTP server
2021/06/07 16:20:20 DEBUG : FTP Rx: "220 ProFTPD Server (dev14.keymachine.de FTP-Server) [::ffff:62.141.57.77]"
2021/06/07 16:20:20 DEBUG : FTP Tx: "AUTH TLS"
2021/06/07 16:20:20 DEBUG : FTP Rx: "234 AUTH TLS successful"
2021/06/07 16:20:20 DEBUG : FTP Tx: "USER backup_test"
2021/06/07 16:20:20 DEBUG : FTP Rx: "331 Password required for backup_test"
2021/06/07 16:20:20 DEBUG : FTP Tx: PASS *****
2021/06/07 16:20:20 DEBUG : FTP Rx: "230 User backup_test logged in"
2021/06/07 16:20:20 DEBUG : FTP Tx: "FEAT"
2021/06/07 16:20:20 DEBUG : FTP Rx: "211-Features:"
2021/06/07 16:20:20 DEBUG : FTP Rx: "211-AUTH TLS"
2021/06/07 16:20:20 DEBUG : FTP Rx: "211-CCC"
2021/06/07 16:20:20 DEBUG : FTP Rx: "211-CLNT"
2021/06/07 16:20:20 DEBUG : FTP Rx: "211-EPRT"
2021/06/07 16:20:20 DEBUG : FTP Rx: "211-EPSV"
2021/06/07 16:20:20 DEBUG : FTP Rx: "211-HOST"
2021/06/07 16:20:20 DEBUG : FTP Rx: "211-LANG en-US.UTF-8;en-US"
2021/06/07 16:20:20 DEBUG : FTP Rx: "211-MDTM"
2021/06/07 16:20:20 DEBUG : FTP Rx: "211-MFF modify;UNIX.group;UNIX.mode;"
2021/06/07 16:20:20 DEBUG : FTP Rx: "211-MFMT"
2021/06/07 16:20:20 DEBUG : FTP Rx: "211-MLST modify*;perm*;size*;type*;unique*;UNIX.group*;UNIX.groupname*;UNIX.mode*;UNIX.owner*;UNIX.ownername*;"
2021/06/07 16:20:20 DEBUG : FTP Rx: "211-PBSZ"
2021/06/07 16:20:20 DEBUG : FTP Rx: "211-PROT"
2021/06/07 16:20:20 DEBUG : FTP Rx: "211-REST STREAM"
2021/06/07 16:20:20 DEBUG : FTP Rx: "211-SITE MKDIR"
2021/06/07 16:20:20 DEBUG : FTP Rx: "211-SITE RMDIR"
2021/06/07 16:20:20 DEBUG : FTP Rx: "211-SITE SYMLINK"
2021/06/07 16:20:20 DEBUG : FTP Rx: "211-SITE UTIME"
2021/06/07 16:20:20 DEBUG : FTP Rx: "211-SIZE"
2021/06/07 16:20:20 DEBUG : FTP Rx: "211-SSCN"
2021/06/07 16:20:20 DEBUG : FTP Rx: "211-TVFS"
2021/06/07 16:20:20 DEBUG : FTP Rx: "211-UTF8"
2021/06/07 16:20:20 DEBUG : FTP Rx: "211 End"
2021/06/07 16:20:20 DEBUG : FTP Tx: "TYPE I"
2021/06/07 16:20:20 DEBUG : FTP Rx: "200 Type set to I"
2021/06/07 16:20:20 DEBUG : FTP Tx: "PBSZ 0"
2021/06/07 16:20:20 DEBUG : FTP Rx: "200 PBSZ 0 successful"
2021/06/07 16:20:20 DEBUG : FTP Tx: "PROT P"
2021/06/07 16:20:20 DEBUG : FTP Rx: "200 Protection set to Private"
2021/06/07 16:20:20 DEBUG : FTP Tx: "EPSV"
2021/06/07 16:20:20 DEBUG : FTP Rx: "229 Entering Extended Passive Mode (|||30265|)"
2021/06/07 16:20:20 DEBUG : FTP Tx: "LIST /files/alex/www"
2021/06/07 16:20:20 DEBUG : FTP Rx: "150 Opening BINARY mode data connection for file list"
2021/06/07 16:20:20 DEBUG : FTP Rx: "226 Transfer complete"
2021/06/07 16:20:20 DEBUG : FTP Tx: "DELE /files/alex/www/godot-3.3.1-stable.zip"
2021/06/07 16:20:20 DEBUG : FTP Rx: "250 DELE command successful"
2021/06/07 16:20:20 DEBUG : godot-3.3.1-stable.zip: Removed after failed upload: 450 Transfer aborted. Link to file server lost
2021/06/07 16:20:20 ERROR : godot-3.3.1-stable.zip: Failed to copy: update stor: 450 Transfer aborted. Link to file server lost
2021/06/07 16:20:20 ERROR : Attempt 1/1 failed with 1 errors and: update stor: 450 Transfer aborted. Link to file server lost
2021/06/07 16:20:20 INFO  : 
Transferred:   	   33.692M / 33.692 MBytes, 100%, 16.092 MBytes/s, ETA 0s
Errors:                 1 (retrying may help)
Elapsed time:         2.4s

2021/06/07 16:20:20 DEBUG : 2 go routines active
2021/06/07 16:20:20 Failed to copy: update stor: 450 Transfer aborted. Link to file server lost

Remote servers

On the remote side, I'm using ProFTPD. I tested 3 different operating systems with each an other version of ProFTPD.

  • an Ubuntu 20 - ProFTPD Version 1.3.6c
  • an Ubuntu 18 - ProFTPD Version 1.3.5e
  • a Debian 10 - ProFTPD Version 1.3.6

The error remains the same.

All servers have a valid Let's Encrypt certificate which is used also to protect the ProFTPD server.
FTP on these servers is running fine, besides when using Rclone + FTPS in explicit mode.

ProFTPD Log output of a remote server | Ubuntu 20.04 - ProFTPD 1.3.6e

/var/log/proftpd/tls.log

2021-06-07 14:07:55,733 mod_tls/2.7[2741251]: TLS/TLS-C requested, starting TLS handshake
2021-06-07 14:07:55,800 mod_tls/2.7[2741251]: TLSv1.3 connection accepted, using cipher TLS_CHACHA20_POLY1305_SHA256 (256 bits)
2021-06-07 14:07:55,990 mod_tls/2.7[2741251]: Protection set to Private
2021-06-07 14:07:55,994 mod_tls/2.7[2741251]: starting TLS negotiation on data connection
2021-06-07 14:07:56,009 mod_tls/2.7[2741251]: TLSv1.3 data connection accepted, using cipher TLS_CHACHA20_POLY1305_SHA256 (256 bits)
2021-06-07 14:07:56,013 mod_tls/2.7[2741251]: starting TLS negotiation on data connection
2021-06-07 14:07:56,031 mod_tls/2.7[2741251]: starting TLS negotiation on data connection
2021-06-07 14:07:56,050 mod_tls/2.7[2741251]: starting TLS negotiation on data connection
2021-06-07 14:07:57,726 mod_tls/2.7[2741252]: TLS/TLS-C requested, starting TLS handshake
2021-06-07 14:07:57,743 mod_tls/2.7[2741252]: TLSv1.3 connection accepted, using cipher TLS_CHACHA20_POLY1305_SHA256 (256 bits)
2021-06-07 14:07:57,926 mod_tls/2.7[2741252]: Protection set to Private
2021-06-07 14:07:57,928 mod_tls/2.7[2741252]: starting TLS negotiation on data connection
2021-06-07 14:07:57,942 mod_tls/2.7[2741252]: TLSv1.3 data connection accepted, using cipher TLS_CHACHA20_POLY1305_SHA256 (256 bits)

/var/log/proftpd/proftpd.log

2021-06-07 14:07:56,707 dev14.keymachine.de proftpd[2741251] dev14.keymachine.de (ns2.dev01.keymachine.de[62.141.57.104]): notice: user backup_test: aborting transfer: Link to file server lost

/var/log/proftpd/xferlog

Mon Jun 07 14:07:56 2021 0 ns2.dev01.keymachine.de 34844672 /home/users/backup_test/files/alex/www/godot-3.3.1-stable.zip b _ i r backup_test ftps 0 * i
Mon Jun 07 14:07:57 2021 0 ns2.dev01.keymachine.de 34844672 /home/users/backup_test/files/alex/www/godot-3.3.1-stable.zip b _ d r backup_test ftps 0 * c

Further note

EDIT: I have found this Rclone copy to FTP: rclone sends a QUIT and never ends itself - #12 by ivandeex, at least I am not alone with this issue ;).

Thank you very much for your help!
Alex

Is that the same issue?

Can you try the fix here

Can you try the fix here

The fix is experimental. Please don't use it.

I tried the fix from ivandeex - just for testing purposes. Unfortunately also without success. The overall picture remains the same, some files work, others don't.

Anyway, I tried another remote server, this time with a differently set up ProFTPD instance. Here the data transfer works without errors.

I will now check if I can find the difference between these servers. I will report again.

Thank you very much in advance.

Look forward to hearing your results. It sounds like there is something off in the FTP client so I hope we can put our collective fingers on it!

Good news, it seems the problem is ProFTPD in version < 1.3.7rc4 when using TLS 1.3
=> Rclone has nothing to do with it.

With ProFTPD 1.3.7a the data transfer worked. So I checked the changelog of ProFTPD and found that there was a fix for a problem: "Fixed issue with FTPS uploads of large files using TLSv1.3 (Issue #959)." (FTPS uploads using TLSv1.3 are likely to fail unexpectedly · Issue #959 · proftpd/proftpd · GitHub)

(By the way, "large" means 200 KB :wink: )

So I tried TLS 1.2 and it worked.

Sorry to have burdened you with this. Rclone is great :wink:

1 Like

@icom
Great find.
Seems like Hetzner is using older ProFTPd.
I can ask them to upgrade but it's gonna be long.

@ncw
Is there a way in golang/rclone to enforce TLS 1.2 and opt out from TLS 1.3 ?
Something like GODEBUG=tls13=0 ?

You can do it by meddling with the TLS options

    // MinVersion contains the minimum TLS version that is acceptable.
    // If zero, TLS 1.0 is currently taken as the minimum.
    MinVersion uint16 // Go 1.2

    // MaxVersion contains the maximum TLS version that is acceptable.
    // If zero, the maximum version supported by this package is used,
    // which is currently TLS 1.3.
    MaxVersion uint16 // Go 1.2

We could maybe make global flags for these and put them in httplib though that might not catch the FTP client usage.

There aren't any env vars (I checked in the source).

I tried to disable TLS 1.3 with FTP on this branch: Commits · ivandeex/rclone · GitHub
Downloading from Hetzner storage box (explicit tls, disable tls 1.3) still broken - TLS stream internally seeks to 0 after ~700M, repeatedly.
Will submit a request to Hetzner asking to upgrade ProFTPd. That's gonna be long.
Will keep on using SFTP for now.

2 Likes

This topic was automatically closed 3 days after the last reply. New replies are no longer allowed.