Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

425 Unable to build data connection: TLS session of data connection not resumed #7234

Closed
PhilMakower opened this issue Aug 17, 2023 · 9 comments

Comments

@PhilMakower
Copy link

The associated forum post URL from https://forum.rclone.org

https://forum.rclone.org/t/rclone-mount-425-unable-to-build-data-connection-tls-session-of-data-connection-not-resumed/40038

What is the problem you are having with rclone?

doing sync to FileZilla server remote using explicit TLS and concurrency > 1 results in some 425 errors.

Doing sync to PureFTP servers with explicit TLS and default concurrency OK
Doing sync to FileZilla server without explicit TLS and default concrrency OK

What is your rclone version (output from rclone version)

rclone v1.64.0-beta.7240.34195fd3e
- os/version: ubuntu 18.04 (64 bit)
- os/kernel: 4.15.0-213-generic (x86_64)
- os/type: linux
- os/arch: amd64
- go/version: go1.21.0
- go/linking: static
- go/tags: none

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

client Ubuntu 18 64 bit
Server Window 2019 64 bit

Which cloud storage system are you using? (e.g. Google Drive)

ftp

The command you were trying to run (e.g. rclone copy /tmp remote:tmp)

rclone sync :ftp: . --ftp-host=io19.blackpig.net --ftp-user="acuitus.onproof.net" --ftp-pass=*** --ftp-disable-epsv=true --ftp-explicit-tls --filter-from ~/ftpsync.blackpig.net/filter-rclone-sites.txt --skip-links -vv

A log from the command with the -vv flag (e.g. output from rclone -vv copy /tmp remote:tmp)

(first timestamp is UTC from log of script that calls rclone)

2023/08/17 07:53:16 cmd rclone sync :ftp: . --ftp-host=io19.blackpig.net --ftp-user="acuitus.onproof.net" --ftp-pass=***
--ftp-disable-epsv=true --ftp-explicit-tls --filter-from ~/ftpsync.blackpig.net/filter-rclone-sites.txt --skip-links -vv
2023/08/17 07:53:18 rclone: 2023/08/17 08:53:18 DEBUG : rclone: Version "v1.64.0-beta.7240.34195fd3e" starting with parameters ["rclone" "sync" ":ftp:" "." "--ftp-host=io19.blackpig.net" "--ftp-user=acuitus.onproof.net" "--ftp-pass=***" "--ftp-disable-epsv=true" "--ftp-explicit-tls" "--filter-from" "/root/ftpsync.blackpig.net/filter-rclone-sites.txt" "--skip-links" "-vv"]
2023/08/17 07:53:18 rclone: 2023/08/17 08:53:18 DEBUG : Creating backend with remote ":ftp:"
2023/08/17 07:53:18 rclone: 2023/08/17 08:53:18 DEBUG : Using config file from "/root/.config/rclone/rclone.conf"
2023/08/17 07:53:18 rclone: 2023/08/17 08:53:18 DEBUG : :ftp: detected overridden config - adding "{0t1LJ}" suffix to name
2023/08/17 07:53:18 rclone: 2023/08/17 08:53:18 DEBUG : ftp://io19.blackpig.net:21: Connecting to FTP server
2023/08/17 07:53:18 rclone: 2023/08/17 08:53:18 DEBUG : ftp://io19.blackpig.net:21: dial("tcp","io19.blackpig.net:21")
2023/08/17 07:53:18 rclone: 2023/08/17 08:53:18 DEBUG : ftp://io19.blackpig.net:21: > dial: conn=*fshttp.timeoutConn, err=<nil>
2023/08/17 07:53:18 rclone: 2023/08/17 08:53:18 DEBUG : fs cache: renaming cache item ":ftp:" to be canonical ":ftp{0t1LJ}:"
2023/08/17 07:53:18 rclone: 2023/08/17 08:53:18 DEBUG : Creating backend with remote "."
2023/08/17 07:53:18 rclone: 2023/08/17 08:53:18 DEBUG : local: detected overridden config - adding "{HK82T}" suffix to name
2023/08/17 07:53:18 rclone: 2023/08/17 08:53:18 DEBUG : fs cache: renaming cache item "." to be canonical "local{HK82T}:/data/ftpsync/acuitus.onproof.net"
2023/08/17 07:53:18 rclone: 2023/08/17 08:53:18 DEBUG : _sql: Excluded
2023/08/17 07:53:18 rclone: 2023/08/17 08:53:18 DEBUG : _backup: Excluded
2023/08/17 07:53:18 rclone: 2023/08/17 08:53:18 DEBUG : _sync: Excluded
2023/08/17 07:53:18 rclone: 2023/08/17 08:53:18 DEBUG : _mysql: Excluded
2023/08/17 07:53:18 rclone: 2023/08/17 08:53:18 DEBUG : ftp://io19.blackpig.net:21: dial("tcp","78.31.110.103:58490")
2023/08/17 07:53:18 rclone: 2023/08/17 08:53:18 DEBUG : ftp://io19.blackpig.net:21: > dial: conn=*tls.Conn, err=<nil>
2023/08/17 07:53:18 rclone: 2023/08/17 08:53:18 DEBUG : _backup: Excluded
2023/08/17 07:53:18 rclone: 2023/08/17 08:53:18 DEBUG : HLP_OB_220729_9150.jpg: Size and modification time the same (differ by 0s, within tolerance 1s)
...
2023/08/17 07:53:18 rclone: 2023/08/17 08:53:18 DEBUG : wp-config.php: Unchanged skipping
2023/08/17 07:53:18 rclone: 2023/08/17 08:53:18 DEBUG : ftp://io19.blackpig.net:21: Connecting to FTP server
2023/08/17 07:53:18 rclone: 2023/08/17 08:53:18 DEBUG : ftp://io19.blackpig.net:21: Connecting to FTP server
2023/08/17 07:53:18 rclone: 2023/08/17 08:53:18 DEBUG : ftp://io19.blackpig.net:21: dial("tcp","io19.blackpig.net:21")
2023/08/17 07:53:18 rclone: 2023/08/17 08:53:18 DEBUG : ftp://io19.blackpig.net:21: Connecting to FTP server
2023/08/17 07:53:18 rclone: 2023/08/17 08:53:18 DEBUG : ftp://io19.blackpig.net:21: Connecting to FTP server
2023/08/17 07:53:18 rclone: 2023/08/17 08:53:18 DEBUG : ftp://io19.blackpig.net:21: Connecting to FTP server
2023/08/17 07:53:18 rclone: 2023/08/17 08:53:18 DEBUG : ftp://io19.blackpig.net:21: Connecting to FTP server
2023/08/17 07:53:18 rclone: 2023/08/17 08:53:18 DEBUG : ftp://io19.blackpig.net:21: Connecting to FTP server
2023/08/17 07:53:18 rclone: 2023/08/17 08:53:18 DEBUG : ftp://io19.blackpig.net:21: dial("tcp","78.31.110.103:60903")
2023/08/17 07:53:18 rclone: 2023/08/17 08:53:18 DEBUG : ftp://io19.blackpig.net:21: > dial: conn=*tls.Conn, err=<nil>
2023/08/17 07:53:18 rclone: 2023/08/17 08:53:18 DEBUG : ftp://io19.blackpig.net:21: dial("tcp","io19.blackpig.net:21")
2023/08/17 07:53:18 rclone: 2023/08/17 08:53:18 DEBUG : ftp://io19.blackpig.net:21: > dial: conn=*fshttp.timeoutConn, err=<nil>
2023/08/17 07:53:18 rclone: 2023/08/17 08:53:18 DEBUG : ftp://io19.blackpig.net:21: > dial: conn=*fshttp.timeoutConn, err=<nil>
2023/08/17 07:53:18 rclone: 2023/08/17 08:53:18 DEBUG : ftp://io19.blackpig.net:21: dial("tcp","io19.blackpig.net:21")
...
2023/08/17 07:53:19 rclone: 2023/08/17 08:53:19 DEBUG : _transfer/WCFauctionsLibrary.pdb: Unchanged skipping
2023/08/17 07:53:19 rclone: 2023/08/17 08:53:19 DEBUG : ftp://io19.blackpig.net:21: > dial: conn=*tls.Conn, err=<nil>
2023/08/17 07:53:19 rclone: 2023/08/17 08:53:19 DEBUG : ftp://io19.blackpig.net:21: dial("tcp","78.31.110.103:59577")
2023/08/17 07:53:19 rclone: 2023/08/17 08:53:19 DEBUG : ftp://io19.blackpig.net:21: dial("tcp","78.31.110.103:51703")
2023/08/17 07:53:19 rclone: 2023/08/17 08:53:19 DEBUG : ftp://io19.blackpig.net:21: > dial: conn=*tls.Conn, err=<nil>
2023/08/17 07:53:19 rclone: 2023/08/17 08:53:19 DEBUG : ftp://io19.blackpig.net:21: > dial: conn=*tls.Conn, err=<nil>
2023/08/17 07:53:19 rclone: 2023/08/17 08:53:19 DEBUG : ftp://io19.blackpig.net:21: dial("tcp","78.31.110.103:55510")
2023/08/17 07:53:19 rclone: 2023/08/17 08:53:19 DEBUG : ftp://io19.blackpig.net:21: dial("tcp","78.31.110.103:60754")
2023/08/17 07:53:19 rclone: 2023/08/17 08:53:19 DEBUG : ftp://io19.blackpig.net:21: dial("tcp","78.31.110.103:63158")
2023/08/17 07:53:19 rclone: 2023/08/17 08:53:19 DEBUG : ftp://io19.blackpig.net:21: > dial: conn=*tls.Conn, err=<nil>
2023/08/17 07:53:19 rclone: 2023/08/17 08:53:19 DEBUG : ftp://io19.blackpig.net:21: dial("tcp","78.31.110.103:63510")
2023/08/17 07:53:19 rclone: 2023/08/17 08:53:19 DEBUG : ftp://io19.blackpig.net:21: dial("tcp","78.31.110.103:61800")
2023/08/17 07:53:19 rclone: 2023/08/17 08:53:19 DEBUG : ftp://io19.blackpig.net:21: > dial: conn=*tls.Conn, err=<nil>
2023/08/17 07:53:19 rclone: 2023/08/17 08:53:19 DEBUG : ftp://io19.blackpig.net:21: > dial: conn=*tls.Conn, err=<nil>
2023/08/17 07:53:19 rclone: 2023/08/17 08:53:19 DEBUG : ftp://io19.blackpig.net:21: > dial: conn=*tls.Conn, err=<nil>
2023/08/17 07:53:19 rclone: 2023/08/17 08:53:19 DEBUG : ftp://io19.blackpig.net:21: > dial: conn=*tls.Conn, err=<nil>
2023/08/17 07:53:19 rclone: 2023/08/17 08:53:19 ERROR : PDFlib-910-MSWin64-php: error reading source directory: 1 error occurred:
2023/08/17 07:53:19 rclone: * 425 Unable to build data connection: TLS session of data connection not resumed.
2023/08/17 07:53:19 rclone: 2023/08/17 08:53:19 ERROR : _auctions: error reading source directory: 1 error occurred:
2023/08/17 07:53:19 rclone: * 425 Unable to build data connection: TLS session of data connection not resumed.
2023/08/17 07:53:19 rclone: 2023/08/17 08:53:19 ERROR : aspnet_client: error reading source directory: 1 error occurred:
2023/08/17 07:53:19 rclone: * 425 Unable to build data connection: TLS session of data connection not resumed.
2023/08/17 07:53:19 rclone: 2023/08/17 08:53:19 DEBUG : Notifications/AcuitusNotifierApp.exe: Size and modification time the same (differ by 0s, within tolerance 1s)
...
2023/08/17 07:53:19 rclone: 2023/08/17 08:53:19 DEBUG : Notifications/HtmlDiff.pdb: Size and modification time the same (differ by 0s, within tolerance 1s)
2023/08/17 07:53:19 rclone: 2023/08/17 08:53:19 DEBUG : Notifications/HtmlDiff.pdb: Unchanged skipping
2023/08/17 07:53:19 rclone: 2023/08/17 08:53:19 DEBUG : ftp://io19.blackpig.net:21: dial("tcp","78.31.110.103:64881")
2023/08/17 07:53:19 rclone: 2023/08/17 08:53:19 DEBUG : ftp://io19.blackpig.net:21: dial("tcp","78.31.110.103:65131")
2023/08/17 07:53:19 rclone: 2023/08/17 08:53:19 DEBUG : ftp://io19.blackpig.net:21: dial("tcp","78.31.110.103:63343")
2023/08/17 07:53:19 rclone: 2023/08/17 08:53:19 ERROR : Auctions: error reading source directory: 1 error occurred:
2023/08/17 07:53:19 rclone: * 425 Unable to build data connection: TLS session of data connection not resumed.
2023/08/17 07:53:19 rclone: 2023/08/17 08:53:19 DEBUG : ftp://io19.blackpig.net:21: > dial: conn=*tls.Conn, err=<nil>
2023/08/17 07:53:19 rclone: 2023/08/17 08:53:19 ERROR : app: error reading source directory: 1 error occurred:
2023/08/17 07:53:19 rclone: * 425 Unable to build data connection: TLS session of data connection not resumed.
2023/08/17 07:53:19 rclone: 2023/08/17 08:53:19 DEBUG : ftp://io19.blackpig.net:21: dial("tcp","78.31.110.103:56539")
2023/08/17 07:53:19 rclone: 2023/08/17 08:53:19 DEBUG : ftp://io19.blackpig.net:21: > dial: conn=*tls.Conn, err=<nil>
2023/08/17 07:53:19 rclone: 2023/08/17 08:53:19 DEBUG : ftp://io19.blackpig.net:21: > dial: conn=*tls.Conn, err=<nil>
2023/08/17 07:53:19 rclone: 2023/08/17 08:53:19 DEBUG : ftp://io19.blackpig.net:21: > dial: conn=*tls.Conn, err=<nil>
2023/08/17 07:53:19 rclone: 2023/08/17 08:53:19 DEBUG : ftp://io19.blackpig.net:21: dial("tcp","78.31.110.103:62814")
2023/08/17 07:53:19 rclone: 2023/08/17 08:53:19 DEBUG : ftp://io19.blackpig.net:21: > dial: conn=*tls.Conn, err=<nil>
2023/08/17 07:53:19 rclone: 2023/08/17 08:53:19 DEBUG : ftp://io19.blackpig.net:21: dial("tcp","78.31.110.103:54513")
2023/08/17 07:53:19 rclone: 2023/08/17 08:53:19 DEBUG : ftp://io19.blackpig.net:21: > dial: conn=*tls.Conn, err=<nil>
2023/08/17 07:53:20 rclone: 2023/08/17 08:53:20 ERROR : components: error reading source directory: 1 error occurred:
2023/08/17 07:53:20 rclone: * 425 Unable to build data connection: TLS session of data connection not resumed.
2023/08/17 07:53:20 rclone: 2023/08/17 08:53:20 ERROR : App_Backup: error reading source directory: 1 error occurred:
2023/08/17 07:53:20 rclone: * 425 Unable to build data connection: TLS session of data connection not resumed.
2023/08/17 07:53:20 rclone: 2023/08/17 08:53:20 DEBUG : emails/addendum.html: Size and modification time the same (differ by 0s, within tolerance 1s)
...
2023/08/17 07:53:21 rclone: 2023/08/17 08:53:20 DEBUG : Local file system at /data/ftpsync/acuitus.onproof.net: Waiting for transfers to finish
2023/08/17 07:53:21 rclone: 2023/08/17 08:53:20 ERROR : Local file system at /data/ftpsync/acuitus.onproof.net: not deleting files as there were IO errors
2023/08/17 07:53:21 rclone: 2023/08/17 08:53:20 ERROR : Local file system at /data/ftpsync/acuitus.onproof.net: not deleting directories as there were IO errors
2023/08/17 07:53:21 rclone: 2023/08/17 08:53:20 ERROR : Attempt 3/3 failed with 26 errors and: march failed with 25 error(s): first error: 1 error occurred:
2023/08/17 07:53:21 rclone: * 425 Unable to build data connection: TLS session of data connection not resumed.
2023/08/17 07:53:21 rclone: 2023/08/17 08:53:20 INFO :
2023/08/17 07:53:21 rclone: Transferred: 0 B / 0 B, -, 0 B/s, ETA -
2023/08/17 07:53:21 rclone: Errors: 26 (retrying may help)
2023/08/17 07:53:21 rclone: Checks: 495 / 495, 100%
2023/08/17 07:53:21 rclone: Elapsed time: 2.6s
2023/08/17 07:53:21 rclone: 2023/08/17 08:53:20 DEBUG : 5 go routines active
2023/08/17 07:53:21 rclone: 2023/08/17 08:53:20 DEBUG : ftp://io19.blackpig.net:21: closing 8 unused connections
2023/08/17 07:53:21 rclone: 2023/08/17 08:53:20 Failed to sync with 26 errors: last error was: march failed with 25 error(s): first error: 1 error occurred:
2023/08/17 07:53:21 rclone: * 425 Unable to build data connection: TLS session of data connection not resumed.

How to use GitHub

  • Please use the 👍 reaction to show that you are affected by the same issue.
  • Please don't comment if you have no relevant information to add. It's just extra noise for everyone subscribed to this issue.
  • Subscribe to receive notifications on status change and new comments.
ncw added a commit that referenced this issue Aug 17, 2023
As an extra security feature some FTP servers (eg FileZilla) require
that the data connection re-use the same TLS connection as the control
connection. This is a good thing for security.

The message "TLS session of data connection not resumed" means that it
was not done.

The problem turned out to be that rclone was re-using the TLS session
cache between concurrent connections so the resumed TLS data
connection could from any of the control connections.

This patch makes each TLS connection have its own session cache which
should fix the problem.

Fixes #7234
@ncw
Copy link
Member

ncw commented Aug 17, 2023

Relevant issue upstream jlaffaye/ftp#342

I added a comment there with the info above (thank you very helpful).

I think what the error TLS session of data connection not resumed actually means is this...

As an extra security feature some FTP servers require that the data connection re-use the same TLS connection as the control connection. This is a good thing for security. However that message means that rclone failed to do that.

Given that this works when concurrency == 1 then what must be happening is that rclone or jlaffaye/ftp is mixing up the streams so we are attempting to do file transfers on the wrong TLS connection.

I think the problem is that we are re-using the session cache between connections so the TLS library has a chance of picking the wrong connection.

Try this which uses a different session cache for each connection and should hopefully fix the problem.

v1.64.0-beta.7241.6efb5de13.fix-7234-ftp-tls on branch fix-7234-ftp-tls (uploaded in 15-30 mins)

@PhilMakower
Copy link
Author

the new beta doesn't work even when concurrency=1

(2023/08/17 12:23:15) rclone: 2023/08/17 13:23:15 DEBUG : rclone: Version "v1.64.0-beta.7241.6efb5de13.fix-7234-ftp-tls" starting with parameters ["rclone" "sync" ":ftp:" "." "--ftp-host=io19.blackpig.net" "--ftp-user=acuitus.onproof.net" "--ftp-pass=***" "--ftp-disable-epsv=true" "--ftp-explicit-tls" "--ftp-concurrency=1" "--filter-from" "/root/ftpsync.blackpig.net/filter-rclone-sites.txt" "--skip-links" "-vv"]
(2023/08/17 12:23:15) rclone: 2023/08/17 13:23:15 DEBUG : Creating backend with remote ":ftp:"
(2023/08/17 12:23:15) rclone: 2023/08/17 13:23:15 DEBUG : Using config file from "/root/.config/rclone/rclone.conf"
(2023/08/17 12:23:15) rclone: 2023/08/17 13:23:15 DEBUG : :ftp: detected overridden config - adding "{Pbn1p}" suffix to name
(2023/08/17 12:23:15) rclone: 2023/08/17 13:23:15 DEBUG : ftp://io19.blackpig.net:21: Connecting to FTP server
(2023/08/17 12:23:15) rclone: 2023/08/17 13:23:15 DEBUG : ftp://io19.blackpig.net:21: dial("tcp","io19.blackpig.net:21")
(2023/08/17 12:23:15) rclone: 2023/08/17 13:23:15 DEBUG : ftp://io19.blackpig.net:21: > dial: conn=*fshttp.timeoutConn, err=<nil>
(2023/08/17 12:23:15) rclone: 2023/08/17 13:23:15 DEBUG : fs cache: renaming cache item ":ftp:" to be canonical ":ftp{Pbn1p}:"
(2023/08/17 12:23:15) rclone: 2023/08/17 13:23:15 DEBUG : Creating backend with remote "."
(2023/08/17 12:23:15) rclone: 2023/08/17 13:23:15 DEBUG : local: detected overridden config - adding "{HK82T}" suffix to name
(2023/08/17 12:23:15) rclone: 2023/08/17 13:23:15 DEBUG : fs cache: renaming cache item "." to be canonical "local{HK82T}:/data/ftpsync/acuitus.onproof.net"
(2023/08/17 12:23:15) rclone: 2023/08/17 13:23:15 DEBUG : _sql: Excluded
(2023/08/17 12:23:15) rclone: 2023/08/17 13:23:15 DEBUG : _backup: Excluded
(2023/08/17 12:23:15) rclone: 2023/08/17 13:23:15 DEBUG : _sync: Excluded
(2023/08/17 12:23:15) rclone: 2023/08/17 13:23:15 DEBUG : _mysql: Excluded
(2023/08/17 12:23:15) rclone: 2023/08/17 13:23:15 DEBUG : ftp://io19.blackpig.net:21: dial("tcp","78.31.110.103:59087")
(2023/08/17 12:23:15) rclone: 2023/08/17 13:23:15 DEBUG : ftp://io19.blackpig.net:21: > dial: conn=*tls.Conn, err=<nil>
(2023/08/17 12:23:16) ERROR: rclone: 2023/08/17 13:23:16 ERROR : ftp://io19.blackpig.net:21: error reading source root directory: 1 error occurred:
(2023/08/17 12:23:16) rclone: * 425 Unable to build data connection: TLS session of data connection not resumed.
(2023/08/17 12:23:16) rclone: 2023/08/17 13:23:16 DEBUG : Local file system at /data/ftpsync/acuitus.onproof.net: Waiting for checks to finish
(2023/08/17 12:23:16) rclone: 2023/08/17 13:23:16 DEBUG : Local file system at /data/ftpsync/acuitus.onproof.net: Waiting for transfers to finish
(2023/08/17 12:23:16) ERROR: rclone: 2023/08/17 13:23:16 ERROR : Local file system at /data/ftpsync/acuitus.onproof.net: not deleting files as there were IO errors
(2023/08/17 12:23:16) ERROR: rclone: 2023/08/17 13:23:16 ERROR : Local file system at /data/ftpsync/acuitus.onproof.net: not deleting directories as there were IO errors
(2023/08/17 12:23:16) ERROR: rclone: 2023/08/17 13:23:16 ERROR : Attempt 1/3 failed with 1 errors and: 1 error occurred:
(2023/08/17 12:23:16) rclone: * 425 Unable to build data connection: TLS session of data connection not resumed.
(2023/08/17 12:23:16) rclone: 2023/08/17 13:23:16 DEBUG : _sql: Excluded
(2023/08/17 12:23:16) rclone: 2023/08/17 13:23:16 DEBUG : _backup: Excluded
(2023/08/17 12:23:16) rclone: 2023/08/17 13:23:16 DEBUG : _sync: Excluded
(2023/08/17 12:23:16) rclone: 2023/08/17 13:23:16 DEBUG : _mysql: Excluded
(2023/08/17 12:23:16) rclone: 2023/08/17 13:23:16 DEBUG : ftp://io19.blackpig.net:21: dial("tcp","78.31.110.103:50661")
(2023/08/17 12:23:16) rclone: 2023/08/17 13:23:16 DEBUG : ftp://io19.blackpig.net:21: > dial: conn=*tls.Conn, err=<nil>
(2023/08/17 12:23:16) ERROR: rclone: 2023/08/17 13:23:16 ERROR : ftp://io19.blackpig.net:21: error reading source root directory: 1 error occurred:
(2023/08/17 12:23:16) rclone: * 425 Unable to build data connection: TLS session of data connection not resumed.
(2023/08/17 12:23:16) rclone: 2023/08/17 13:23:16 DEBUG : Local file system at /data/ftpsync/acuitus.onproof.net: Waiting for checks to finish
(2023/08/17 12:23:16) rclone: 2023/08/17 13:23:16 DEBUG : Local file system at /data/ftpsync/acuitus.onproof.net: Waiting for transfers to finish
(2023/08/17 12:23:16) ERROR: rclone: 2023/08/17 13:23:16 ERROR : Local file system at /data/ftpsync/acuitus.onproof.net: not deleting files as there were IO errors
(2023/08/17 12:23:16) ERROR: rclone: 2023/08/17 13:23:16 ERROR : Local file system at /data/ftpsync/acuitus.onproof.net: not deleting directories as there were IO errors
(2023/08/17 12:23:16) ERROR: rclone: 2023/08/17 13:23:16 ERROR : Attempt 2/3 failed with 1 errors and: 1 error occurred:
(2023/08/17 12:23:16) rclone: * 425 Unable to build data connection: TLS session of data connection not resumed.
(2023/08/17 12:23:16) rclone: 2023/08/17 13:23:16 DEBUG : _sql: Excluded
(2023/08/17 12:23:16) rclone: 2023/08/17 13:23:16 DEBUG : _backup: Excluded
(2023/08/17 12:23:16) rclone: 2023/08/17 13:23:16 DEBUG : _sync: Excluded
(2023/08/17 12:23:16) rclone: 2023/08/17 13:23:16 DEBUG : _mysql: Excluded
(2023/08/17 12:23:16) rclone: 2023/08/17 13:23:16 DEBUG : ftp://io19.blackpig.net:21: dial("tcp","78.31.110.103:59217")
(2023/08/17 12:23:16) rclone: 2023/08/17 13:23:16 DEBUG : ftp://io19.blackpig.net:21: > dial: conn=*tls.Conn, err=<nil>
(2023/08/17 12:23:16) ERROR: rclone: 2023/08/17 13:23:16 ERROR : ftp://io19.blackpig.net:21: error reading source root directory: 1 error occurred:
(2023/08/17 12:23:16) rclone: * 425 Unable to build data connection: TLS session of data connection not resumed.
(2023/08/17 12:23:16) rclone: 2023/08/17 13:23:16 DEBUG : Local file system at /data/ftpsync/acuitus.onproof.net: Waiting for checks to finish
(2023/08/17 12:23:16) rclone: 2023/08/17 13:23:16 DEBUG : Local file system at /data/ftpsync/acuitus.onproof.net: Waiting for transfers to finish
(2023/08/17 12:23:16) ERROR: rclone: 2023/08/17 13:23:16 ERROR : Local file system at /data/ftpsync/acuitus.onproof.net: not deleting files as there were IO errors
(2023/08/17 12:23:16) ERROR: rclone: 2023/08/17 13:23:16 ERROR : Local file system at /data/ftpsync/acuitus.onproof.net: not deleting directories as there were IO errors
(2023/08/17 12:23:16) ERROR: rclone: 2023/08/17 13:23:16 ERROR : Attempt 3/3 failed with 1 errors and: 1 error occurred:
(2023/08/17 12:23:16) rclone: * 425 Unable to build data connection: TLS session of data connection not resumed.
(2023/08/17 12:23:16) rclone: 2023/08/17 13:23:16 INFO  :
(2023/08/17 12:23:16) rclone: Transferred:                0 B / 0 B, -, 0 B/s, ETA -
(2023/08/17 12:23:16) rclone: Errors:                 1 (retrying may help)
(2023/08/17 12:23:16) rclone: Elapsed time:         0.4s
(2023/08/17 12:23:16) rclone: 2023/08/17 13:23:16 DEBUG : 5 go routines active
(2023/08/17 12:23:16) rclone: 2023/08/17 13:23:16 DEBUG : ftp://io19.blackpig.net:21: closing 1 unused connections
(2023/08/17 12:23:16) rclone: 2023/08/17 13:23:16 Failed to sync: 1 error occurred:
(2023/08/17 12:23:16) rclone: * 425 Unable to build data connection: TLS session of data connection not resumed.

@ncw
Copy link
Member

ncw commented Aug 17, 2023

OK. That is obvious when looking at the code since rclone implements a dialler and we are using a different tls.Conf for each connection.

Try this as a test - this uses a new TLS cache for every connection but gets the library to make the connections.

v1.64.0-beta.7242.fe23696ce.fix-7234-ftp-tls on branch fix-7234-ftp-tls (uploaded in 15-30 mins)

If that works, then the upstream library is going to need a patch to make it work with external dial functions as the above test wipes out a huge chunk of rclone's features like rate limiting and proxying.

@PhilMakower
Copy link
Author

Yes this latest beta works fine, the default concurrency picks 8 connections.
The other good news is that it finishes much more quickly, (sync will find mostly unchanged files)

ncw added a commit that referenced this issue Aug 17, 2023
As an extra security feature some FTP servers (eg FileZilla) require
that the data connection re-use the same TLS connection as the control
connection. This is a good thing for security.

The message "TLS session of data connection not resumed" means that it
was not done.

The problem turned out to be that rclone was re-using the TLS session
cache between concurrent connections so the resumed TLS data
connection could from any of the control connections.

This patch makes each TLS connection have its own session cache which
should fix the problem.

This needed to cache the TLS connection in the context which needed a
patch to the upstream library.

Fixes #7234
@ncw
Copy link
Member

ncw commented Aug 17, 2023

OK give this a go - this is a proper fix. This has a patch to the upstream library in it too which if it works for you I'll submit.

v1.64.0-beta.7241.6200e0197.fix-7234-ftp-tls on branch fix-7234-ftp-tls (uploaded in 15-30 mins)

@PhilMakower
Copy link
Author

Sorry, does not work for me :(

2023/08/18 07:55:23 cmd rclone sync :ftp: . --ftp-host=io19.blackpig.net --ftp-user="acuitus.onproof.net" --ftp-pass=*** --ftp-disable-epsv=true --ftp-explicit-tls --filter-from ~/ftpsync.blackpig.net/filter-rclone-sites.txt --skip-links -vv
2023/08/18 07:55:24 rclone: 2023/08/18 08:55:24 DEBUG : rclone: Version "v1.64.0-beta.7241.6200e0197.fix-7234-ftp-tls" starting with parameters ["rclone" "sync" ":ftp:" "." "--ftp-host=io19.blackpig.net" "--ftp-user=acuitus.onproof.net" "--ftp-pass=***" "--ftp-disable-epsv=true" "--ftp-explicit-tls" "--filter-from" "/root/ftpsync.blackpig.net/filter-rclone-sites.txt" "--skip-links" "-vv"]
2023/08/18 07:55:24 rclone: 2023/08/18 08:55:24 DEBUG : Creating backend with remote ":ftp:"
2023/08/18 07:55:24 rclone: 2023/08/18 08:55:24 DEBUG : Using config file from "/root/.config/rclone/rclone.conf"
2023/08/18 07:55:24 rclone: 2023/08/18 08:55:24 DEBUG : :ftp: detected overridden config - adding "{pn9by}" suffix to name
2023/08/18 07:55:24 rclone: 2023/08/18 08:55:24 DEBUG : ftp://io19.blackpig.net:21: Connecting to FTP server
2023/08/18 07:55:24 rclone: 2023/08/18 08:55:24 DEBUG : ftp://io19.blackpig.net:21: dial("tcp","io19.blackpig.net:21")
2023/08/18 07:55:24 rclone: 2023/08/18 08:55:24 DEBUG : ftp://io19.blackpig.net:21: > dial: conn=*fshttp.timeoutConn, err=<nil>
2023/08/18 07:55:25 rclone: 2023/08/18 08:55:25 DEBUG : fs cache: renaming cache item ":ftp:" to be canonical ":ftp{pn9by}:"
2023/08/18 07:55:25 rclone: 2023/08/18 08:55:25 DEBUG : Creating backend with remote "."
2023/08/18 07:55:25 rclone: 2023/08/18 08:55:25 DEBUG : local: detected overridden config - adding "{HK82T}" suffix to name
2023/08/18 07:55:25 rclone: 2023/08/18 08:55:25 DEBUG : fs cache: renaming cache item "." to be canonical "local{HK82T}:/data/ftpsync/acuitus.onproof.net"
2023/08/18 07:55:25 rclone: 2023/08/18 08:55:25 DEBUG : _sql: Excluded
2023/08/18 07:55:25 rclone: 2023/08/18 08:55:25 DEBUG : _backup: Excluded
2023/08/18 07:55:25 rclone: 2023/08/18 08:55:25 DEBUG : _sync: Excluded
2023/08/18 07:55:25 rclone: 2023/08/18 08:55:25 DEBUG : _mysql: Excluded
2023/08/18 07:55:25 rclone: 2023/08/18 08:55:25 DEBUG : ftp://io19.blackpig.net:21: dial("tcp","78.31.110.103:65014")
2023/08/18 07:55:25 rclone: 2023/08/18 08:55:25 DEBUG : ftp://io19.blackpig.net:21: > dial: conn=*tls.Conn, err=<nil>
2023/08/18 07:55:25 rclone: 2023/08/18 08:55:25 ERROR : ftp://io19.blackpig.net:21: error reading source root directory: 1 error occurred:
2023/08/18 07:55:25 rclone: * 425 Unable to build data connection: TLS session of data connection not resumed.
2023/08/18 07:55:25 rclone: 2023/08/18 08:55:25 DEBUG : Local file system at /data/ftpsync/acuitus.onproof.net: Waiting for checks to finish
2023/08/18 07:55:25 rclone: 2023/08/18 08:55:25 DEBUG : Local file system at /data/ftpsync/acuitus.onproof.net: Waiting for transfers to finish
2023/08/18 07:55:25 rclone: 2023/08/18 08:55:25 ERROR : Local file system at /data/ftpsync/acuitus.onproof.net: not deleting files as there were IO errors
2023/08/18 07:55:25 rclone: 2023/08/18 08:55:25 ERROR : Local file system at /data/ftpsync/acuitus.onproof.net: not deleting directories as there were IO errors
2023/08/18 07:55:25 rclone: 2023/08/18 08:55:25 ERROR : Attempt 1/3 failed with 1 errors and: 1 error occurred:
2023/08/18 07:55:25 rclone: * 425 Unable to build data connection: TLS session of data connection not resumed.
2023/08/18 07:55:25 rclone: 2023/08/18 08:55:25 DEBUG : _sql: Excluded
2023/08/18 07:55:25 rclone: 2023/08/18 08:55:25 DEBUG : _backup: Excluded
2023/08/18 07:55:25 rclone: 2023/08/18 08:55:25 DEBUG : _sync: Excluded
2023/08/18 07:55:25 rclone: 2023/08/18 08:55:25 DEBUG : _mysql: Excluded
2023/08/18 07:55:25 rclone: 2023/08/18 08:55:25 DEBUG : ftp://io19.blackpig.net:21: dial("tcp","78.31.110.103:55503")
2023/08/18 07:55:25 rclone: 2023/08/18 08:55:25 DEBUG : ftp://io19.blackpig.net:21: > dial: conn=*tls.Conn, err=<nil>
2023/08/18 07:55:25 rclone: 2023/08/18 08:55:25 ERROR : ftp://io19.blackpig.net:21: error reading source root directory: 1 error occurred:
2023/08/18 07:55:25 rclone: * 425 Unable to build data connection: TLS session of data connection not resumed.
2023/08/18 07:55:25 rclone: 2023/08/18 08:55:25 DEBUG : Local file system at /data/ftpsync/acuitus.onproof.net: Waiting for checks to finish
2023/08/18 07:55:25 rclone: 2023/08/18 08:55:25 DEBUG : Local file system at /data/ftpsync/acuitus.onproof.net: Waiting for transfers to finish
2023/08/18 07:55:25 rclone: 2023/08/18 08:55:25 ERROR : Local file system at /data/ftpsync/acuitus.onproof.net: not deleting files as there were IO errors
2023/08/18 07:55:25 rclone: 2023/08/18 08:55:25 ERROR : Local file system at /data/ftpsync/acuitus.onproof.net: not deleting directories as there were IO errors
2023/08/18 07:55:25 rclone: 2023/08/18 08:55:25 ERROR : Attempt 2/3 failed with 1 errors and: 1 error occurred:
2023/08/18 07:55:25 rclone: * 425 Unable to build data connection: TLS session of data connection not resumed.
2023/08/18 07:55:25 rclone: 2023/08/18 08:55:25 DEBUG : _sql: Excluded
2023/08/18 07:55:25 rclone: 2023/08/18 08:55:25 DEBUG : _backup: Excluded
2023/08/18 07:55:25 rclone: 2023/08/18 08:55:25 DEBUG : _sync: Excluded
2023/08/18 07:55:25 rclone: 2023/08/18 08:55:25 DEBUG : _mysql: Excluded
2023/08/18 07:55:25 rclone: 2023/08/18 08:55:25 DEBUG : ftp://io19.blackpig.net:21: dial("tcp","78.31.110.103:59967")
2023/08/18 07:55:25 rclone: 2023/08/18 08:55:25 DEBUG : ftp://io19.blackpig.net:21: > dial: conn=*tls.Conn, err=<nil>
2023/08/18 07:55:25 rclone: 2023/08/18 08:55:25 ERROR : ftp://io19.blackpig.net:21: error reading source root directory: 1 error occurred:
2023/08/18 07:55:25 rclone: * 425 Unable to build data connection: TLS session of data connection not resumed.
2023/08/18 07:55:25 rclone: 2023/08/18 08:55:25 DEBUG : Local file system at /data/ftpsync/acuitus.onproof.net: Waiting for checks to finish
2023/08/18 07:55:25 rclone: 2023/08/18 08:55:25 DEBUG : Local file system at /data/ftpsync/acuitus.onproof.net: Waiting for transfers to finish
2023/08/18 07:55:25 rclone: 2023/08/18 08:55:25 ERROR : Local file system at /data/ftpsync/acuitus.onproof.net: not deleting files as there were IO errors
2023/08/18 07:55:25 rclone: 2023/08/18 08:55:25 ERROR : Local file system at /data/ftpsync/acuitus.onproof.net: not deleting directories as there were IO errors
2023/08/18 07:55:25 rclone: 2023/08/18 08:55:25 ERROR : Attempt 3/3 failed with 1 errors and: 1 error occurred:
2023/08/18 07:55:25 rclone: * 425 Unable to build data connection: TLS session of data connection not resumed.
2023/08/18 07:55:25 rclone: 2023/08/18 08:55:25 INFO :
2023/08/18 07:55:25 rclone: Transferred: 0 B / 0 B, -, 0 B/s, ETA -
2023/08/18 07:55:25 rclone: Errors: 1 (retrying may help)
2023/08/18 07:55:25 rclone: Elapsed time: 0.4s
2023/08/18 07:55:25 rclone: 2023/08/18 08:55:25 DEBUG : 5 go routines active
2023/08/18 07:55:25 rclone: 2023/08/18 08:55:25 DEBUG : ftp://io19.blackpig.net:21: closing 1 unused connections
2023/08/18 07:55:25 rclone: 2023/08/18 08:55:25 Failed to sync: 1 error occurred:
2023/08/18 07:55:25 rclone: * 425 Unable to build data connection: TLS session of data connection not resumed.

ncw added a commit that referenced this issue Aug 18, 2023
As an extra security feature some FTP servers (eg FileZilla) require
that the data connection re-use the same TLS connection as the control
connection. This is a good thing for security.

The message "TLS session of data connection not resumed" means that it
was not done.

The problem turned out to be that rclone was re-using the TLS session
cache between concurrent connections so the resumed TLS data
connection could from any of the control connections.

This patch makes each TLS connection have its own session cache which
should fix the problem.

This also reverts the ftp library to the upstream version which now
contains all of our patches.

Fixes #7234
@ncw
Copy link
Member

ncw commented Aug 18, 2023

Sorry, does not work for me :(

Yes there is a logic error in there.

I had a re-think and came up with this. This doesn't require an upstream fix and is very close to the version which did work, so hopefully this will do the trick!

If it doesn't I'll have to work out how to replicate this myself!

v1.64.0-beta.7241.2f9db83ec.fix-7234-ftp-tls on branch fix-7234-ftp-tls (uploaded in 15-30 mins)

@PhilMakower
Copy link
Author

Good news, it works now! Thanks!

@ncw ncw closed this as completed in c979cde Aug 18, 2023
@ncw
Copy link
Member

ncw commented Aug 18, 2023

Thanks for your patience testing this @PhilMakower !

I've merged this to master now which means it will be in the latest beta in 15-30 minutes and released in v1.64

@ncw ncw added this to the v1.64 milestone Aug 18, 2023
leekiernan pushed a commit to leekiernan/rclone that referenced this issue Aug 24, 2023
As an extra security feature some FTP servers (eg FileZilla) require
that the data connection re-use the same TLS connection as the control
connection. This is a good thing for security.

The message "TLS session of data connection not resumed" means that it
was not done.

The problem turned out to be that rclone was re-using the TLS session
cache between concurrent connections so the resumed TLS data
connection could from any of the control connections.

This patch makes each TLS connection have its own session cache which
should fix the problem.

This also reverts the ftp library to the upstream version which now
contains all of our patches.

Fixes rclone#7234
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

2 participants