Data connections with ExplicitTLS hang forever #282

ncw · 2022-09-16T12:32:31Z

Describe the bug

Data connections with TLS Explicit mode seem to be broken

To Reproduce

package main

import (
	"crypto/tls"
	"log"
	"os"
	"time"

	"github.com/jlaffaye/ftp"
)

func main() {
	if len(os.Args) != 4 {
		log.Fatalf("Expecting %s ftp.example.org username password", os.Args[0])
	}
	host, username, password := os.Args[1], os.Args[2], os.Args[3]
	port := "21"

	var tlsConf = &tls.Config{
		ServerName: host,
	}

	c, err := ftp.Dial(host+":"+port,
		ftp.DialWithExplicitTLS(tlsConf),
		ftp.DialWithTimeout(20*time.Second),
		ftp.DialWithDebugOutput(os.Stdout),
	)
	if err != nil {
		log.Fatal(err)
	}

	err = c.Login(username, password)
	if err != nil {
		log.Fatal(err)
	}

	// Make a listing
	entries, err := c.List(".")
	if err != nil {
		log.Fatal(err)
	}
	for _, entry := range entries {
		log.Printf("%#v", entry)
	}

	if err := c.Quit(); err != nil {
		log.Fatal(err)
	}
}

Using this program to connect hangs on the listing

Expected behavior

I expected to see a listing

FTP server

This is connecting to a Hetzner storage box. I've also had reports of the same problem with pureftpd (See rclone/rclone#6426 )

Debug output

220 ProFTPD Server (Hetzner Backup) [::ffff:78.47.22.109]
AUTH TLS
234 AUTH TLS successful
USER uXXXXXX
331 Password required for uXXXXXX
PASS supersecretpassword
230 User uXXXXXX logged in
FEAT
211-Features:
 AUTH TLS
 CCC
 CLNT
 EPRT
 EPSV
 HOST
 LANG fr-FR.UTF-8;fr-FR;en-US.UTF-8;en-US;it-IT.UTF-8;it-IT;es-ES.UTF-8;es-ES;bg-BG.UTF-8;bg-BG;ko-KR.UTF-8;ko-KR;zh-TW.UTF-8;zh-TW;ru-RU.UTF-8;ru-RU;ja-JP.UTF-8;ja-JP;zh-CN.UTF-8;zh-CN
 MDTM
 MFF modify;UNIX.group;UNIX.mode;
 MFMT
 MLST modify*;perm*;size*;type*;unique*;UNIX.group*;UNIX.groupname*;UNIX.mode*;UNIX.owner*;UNIX.ownername*;
 PBSZ
 PROT
 RANG STREAM
 REST STREAM
 SIZE
 SSCN
 TVFS
 UTF8
211 End
TYPE I
200 Type set to I
OPTS UTF8 ON
200 UTF8 set to on
PBSZ 0
200 PBSZ 0 successful
PROT P
200 Protection set to Private
EPSV
229 Entering Extended Passive Mode (|||59900|)
2022/09/16 13:19:41 context deadline exceeded

Additional context

I bisected the problem to this commit 212daf2

commit 212daf295f0e6ae44131ea12ee353a13fca71091
Author: Julien Laffaye <jlaffaye@freebsd.org>
Date:   Mon Feb 28 20:43:42 2022 -0500

    Use tls.DialWithDialer which does the handshake
    
    tls.DialWithDialer also better handle special error cases

 ftp.go | 26 +++-----------------------
 1 file changed, 3 insertions(+), 23 deletions(-)

What appears to be happening is that the connection hangs in the tls Handshake.

If I make this small patch to HEAD everything works fine

--- a/ftp.go
+++ b/ftp.go
@@ -559,7 +559,12 @@ func (c *ServerConn) openDataConn() (net.Conn, error) {
 	}
 
 	if c.options.tlsConfig != nil {
-		return tls.DialWithDialer(&c.options.dialer, "tcp", addr, c.options.tlsConfig)
+		conn, err := c.options.dialer.Dial("tcp", addr)
+		if err != nil {
+			return nil, err
+		}
+		tlsConn := tls.Client(conn, c.options.tlsConfig)
+		return tlsConn, nil
 	}
 
 	return c.options.dialer.Dial("tcp", addr)

BUT if I do a tls.Handshake as well (which is what tls.DialWithDialer) does then it hangs up

--- a/ftp.go
+++ b/ftp.go
@@ -559,7 +559,16 @@ func (c *ServerConn) openDataConn() (net.Conn, error) {
 	}
 
 	if c.options.tlsConfig != nil {
-		return tls.DialWithDialer(&c.options.dialer, "tcp", addr, c.options.tlsConfig)
+		conn, err := c.options.dialer.Dial("tcp", addr)
+		if err != nil {
+			return nil, err
+		}
+		tlsConn := tls.Client(conn, c.options.tlsConfig)
+		err = tlsConn.Handshake()
+		if err != nil {
+			return nil, err
+		}
+		return tlsConn, nil
 	}
 
 	return c.options.dialer.Dial("tcp", addr)

I can only think this is either a bug in Go TLS or a bug in openSSL as used by proftpd and pureftpd, but I'm not sure and I'd appreciate any help!

The text was updated successfully, but these errors were encountered:

In jlaffaye#282 it was discovered that doing the tls Handshake immediately on connection causes some FTP servers (proftpd and pureftpd) to hang. The exact cause of this is unknown, but this patch works around the problem by not doing the Handsake initially, and only doing it at the end if we were attempting to upload a zero length file. Doing the Handshake at the end was originally added in a4e9650 however it got reverted in 212daf2 which used tls.DialWithDialer to do the handshake. Unfortunately tls.DialWithDialer seems to trigger the hanging bug. See: https://forum.rclone.org/t/rclone-ftps-explicit-rclone-touch-empty-files-proftpd-unable-to-build-data-connection-operation-not-permitted/22522 See: rclone/rclone#6426 (comment) Fixes jlaffaye#282

It was discovered that doing the tls Handshake immediately on connection causes some FTP servers (proftpd and pureftpd) to hang. This imports a fix for it by temporarily hard forking jlaffaye/ftp to include the fix submitted as a pull request. See: https://forum.rclone.org/t/rclone-ftps-explicit-rclone-touch-empty-files-proftpd-unable-to-build-data-connection-operation-not-permitted/22522 See: #6426 (comment) See: jlaffaye/ftp#283 See: jlaffaye/ftp#282

alexZaicev · 2022-10-31T09:25:54Z

@jlaffaye I'm seeing the same hang when using TLS for operations that require to open new data connection on the server. Could this be revisited and merged into the lib?

mario-gravel · 2022-12-01T14:19:29Z

Having the same issue with vsftpd server on Debian

Thu Dec  1 09:22:31 2022 [pid 370] CONNECT: Client "127.0.0.1"
Thu Dec  1 09:22:31 2022 [pid 370] FTP response: Client "127.0.0.1", "220 (vsFTPd 3.0.3)"
Thu Dec  1 09:22:31 2022 [pid 370] FTP command: Client "127.0.0.1", "AUTH TLS"
Thu Dec  1 09:22:31 2022 [pid 370] FTP response: Client "127.0.0.1", "234 Proceed with negotiation."
Thu Dec  1 09:22:31 2022 [pid 370] FTP command: Client "127.0.0.1", "USER mariogravel"
Thu Dec  1 09:22:31 2022 [pid 370] [mariogravel] FTP response: Client "127.0.0.1", "331 Please specify the password."
Thu Dec  1 09:22:31 2022 [pid 370] [mariogravel] FTP command: Client "127.0.0.1", "PASS <password>"
Thu Dec  1 09:22:31 2022 [pid 369] [mariogravel] OK LOGIN: Client "127.0.0.1"
Thu Dec  1 09:22:31 2022 [pid 371] [mariogravel] FTP response: Client "127.0.0.1", "230 Login successful."
Thu Dec  1 09:22:31 2022 [pid 371] [mariogravel] FTP command: Client "127.0.0.1", "FEAT"
Thu Dec  1 09:22:31 2022 [pid 371] [mariogravel] FTP response: Client "127.0.0.1", "211-Features:"
Thu Dec  1 09:22:31 2022 [pid 371] [mariogravel] FTP response: Client "127.0.0.1", " AUTH TLS??"
Thu Dec  1 09:22:31 2022 [pid 371] [mariogravel] FTP response: Client "127.0.0.1", " EPRT??"
Thu Dec  1 09:22:31 2022 [pid 371] [mariogravel] FTP response: Client "127.0.0.1", " EPSV??"
Thu Dec  1 09:22:31 2022 [pid 371] [mariogravel] FTP response: Client "127.0.0.1", " MDTM??"
Thu Dec  1 09:22:31 2022 [pid 371] [mariogravel] FTP response: Client "127.0.0.1", " PASV??"
Thu Dec  1 09:22:31 2022 [pid 371] [mariogravel] FTP response: Client "127.0.0.1", " PBSZ??"
Thu Dec  1 09:22:31 2022 [pid 371] [mariogravel] FTP response: Client "127.0.0.1", " PROT??"
Thu Dec  1 09:22:31 2022 [pid 371] [mariogravel] FTP response: Client "127.0.0.1", " REST STREAM??"
Thu Dec  1 09:22:31 2022 [pid 371] [mariogravel] FTP response: Client "127.0.0.1", " SIZE??"
Thu Dec  1 09:22:31 2022 [pid 371] [mariogravel] FTP response: Client "127.0.0.1", " TVFS??"
Thu Dec  1 09:22:31 2022 [pid 371] [mariogravel] FTP response: Client "127.0.0.1", "211 End"
Thu Dec  1 09:22:31 2022 [pid 371] [mariogravel] FTP command: Client "127.0.0.1", "TYPE I"
Thu Dec  1 09:22:31 2022 [pid 371] [mariogravel] FTP response: Client "127.0.0.1", "200 Switching to Binary mode."
Thu Dec  1 09:22:31 2022 [pid 371] [mariogravel] FTP command: Client "127.0.0.1", "PBSZ 0"
Thu Dec  1 09:22:31 2022 [pid 371] [mariogravel] FTP response: Client "127.0.0.1", "200 PBSZ set to 0."
Thu Dec  1 09:22:31 2022 [pid 371] [mariogravel] FTP command: Client "127.0.0.1", "PROT P"
Thu Dec  1 09:22:31 2022 [pid 371] [mariogravel] FTP response: Client "127.0.0.1", "200 PROT now Private."
Thu Dec  1 09:22:31 2022 [pid 371] [mariogravel] FTP command: Client "127.0.0.1", "TYPE I"
Thu Dec  1 09:22:31 2022 [pid 371] [mariogravel] FTP response: Client "127.0.0.1", "200 Switching to Binary mode."
Thu Dec  1 09:22:31 2022 [pid 371] [mariogravel] FTP command: Client "127.0.0.1", "CWD /tmp"
Thu Dec  1 09:22:31 2022 [pid 371] [mariogravel] FTP response: Client "127.0.0.1", "250 Directory successfully changed."
Thu Dec  1 09:22:31 2022 [pid 371] [mariogravel] FTP command: Client "127.0.0.1", "PWD"
Thu Dec  1 09:22:31 2022 [pid 371] [mariogravel] FTP response: Client "127.0.0.1", "257 "/tmp" is the current directory"
Thu Dec  1 09:22:31 2022 [pid 371] [mariogravel] FTP command: Client "127.0.0.1", "PASV"
Thu Dec  1 09:22:31 2022 [pid 371] [mariogravel] FTP response: Client "127.0.0.1", "227 Entering Passive Mode (127,0,0,1,82,70)."

ncw added the defect The code does not work as intended label Sep 16, 2022

ncw mentioned this issue Sep 16, 2022

FTP upload always delete file after upload when file size >40k rclone/rclone#6426

Closed

ncw mentioned this issue Sep 16, 2022

Fix hang when using ExplicitTLS to certain servers. #283

Merged

eliasdaler mentioned this issue Oct 4, 2022

ftp client hangs in 229 Entering Extended Passive Mode (|||5844|) #265

Closed

jlaffaye closed this as completed in 9e39e2c Feb 8, 2023

jlaffaye mentioned this issue May 24, 2023

tls: DialWithDialer timed out #329

Closed

prochac referenced this issue Apr 10, 2024

openDataConn - dial with tlsConfig fix (rollback)

d2e53e1

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Data connections with ExplicitTLS hang forever #282

Data connections with ExplicitTLS hang forever #282

ncw commented Sep 16, 2022

alexZaicev commented Oct 31, 2022

mario-gravel commented Dec 1, 2022 •

edited

Loading

Data connections with ExplicitTLS hang forever #282

Data connections with ExplicitTLS hang forever #282

Comments

ncw commented Sep 16, 2022

alexZaicev commented Oct 31, 2022

mario-gravel commented Dec 1, 2022 • edited Loading

mario-gravel commented Dec 1, 2022 •

edited

Loading