Timeout when using ftps to invoke .List and .NameList (TLS) #253

jpfluger · 2022-03-31T17:58:39Z

Describe the bug
Timeout when using ftps to invoke .List and .NameList. Error is "context deadline exceeded".

Maybe (??) related to an underlying TLS issue - possibly #249 and #252

To Reproduce

c, err = ftp.Dial(
	ftpsString,
        ftp.DialWithTimeout(time.Duration(20)*time.Second), // 20 seconds is default for Filezilla.
	ftp.DialWithExplicitTLS(&tls.Config{InsecureSkipVerify: true}),
	ftp.DialWithDisabledEPSV(true), // both true and false have same error 'context deadline exceeded'
)

// c.Login, as applicable

entries, err := c.List("/dir-to-access") // or use "/" ... same error
if err != nil {
	return err // context deadline exceeded
}

Expected behavior
The list of file names should be retrieved.

FTP server

Globalscape v3.6.3
Public URL: n/a

This is all TLS v1.2. From the hosting provider...

Debug output

220 Welcome to XXXX.XXXXX.XXX
USER [email protected]
331 Password required for [email protected].
PASS XXXXXXXXXXXX
230 Login OK. Proceed.
FEAT
211-Features supported:
 COMB target;source_list
 REST STREAM
 SIZE
 MDTM
 MFMT
 XCRC filename;start;end
 SSCN
 MLST Size*;Modify*;Create;Type*;Unique;Perm*;Lang;Media-Type;CharSet;
 MODE Z 
 XNOP 
 UTF8
 UTF-8
 LANG EN*
 CLNT
211 END
TYPE I
200 Type set to I.
OPTS UTF8 ON
200 Entering UTF-8 mode.
PBSZ 0
200 PBSZ Command OK. Protection buffer size set to 0.
PROT P
200 PROT Command OK. Using Private data connection.
PWD
257 "/" is current folder.
PASV
227 Entering Passive Mode (74,51,209,105,82,8).
failed to list entries of ftp server path '/MY DIRECTORY'; context deadline exceeded

The vendor's ftp-server logged the following commands.

Below is output from the vendor's ftp-server when I connected from within Filezilla from the same development workstation. Notice it succeeded at MLSD but the prior connection using jlaffaye/ftp failed at MLSD (it wasn't present above - timed out after 227 Entering Passive Mode).

Filezilla's client-side output is shown below. This shows success and lists the directory.
The command that failed with jlaffaye/ftp MLSD begins at ftp.line-619 but error occurs lower in the stack in the submission of the tcp data that is issued to the server.

Additional context

Command:	PWD
Trace:	tls_layer_impl::on_read()
Trace:	CFtpControlSocket::OnReceive()
Response:	257 "/" is current folder.
Trace:	CFtpChangeDirOpData::ParseResponse() in state 1
Trace:	CFtpControlSocket::ResetOperation(0)
Trace:	CControlSocket::ResetOperation(0)
Trace:	CFtpChangeDirOpData::Reset(0) in state 1
Trace:	CFtpListOpData::SubcommandResult(0) in state 1
Trace:	CControlSocket::SendNextCommand()
Trace:	CFtpListOpData::Send() in state 2
Trace:	CFtpRawTransferOpData::Send() in state 0
Trace:	CFtpRawTransferOpData::Send() in state 1
Command:	TYPE I
Trace:	tls_layer_impl::on_read()
Trace:	CFtpControlSocket::OnReceive()
Response:	200 Type set to I.
Trace:	CFtpRawTransferOpData::ParseResponse() in state 1
Trace:	CControlSocket::SendNextCommand()
Trace:	CFtpRawTransferOpData::Send() in state 2
Command:	PASV
Trace:	tls_layer_impl::on_read()
Trace:	CFtpControlSocket::OnReceive()
Response:	227 Entering Passive Mode (74,51,209,105,82,8).
Trace:	CFtpRawTransferOpData::ParseResponse() in state 2
Trace:	CControlSocket::SendNextCommand()
Trace:	CFtpRawTransferOpData::Send() in state 4
Trace:	Binding data connection source IP to control connection source IP XXX.XXX.XXX.XXX
Trace:	tls_layer_impl::client_handshake()
Trace:	Trying to resume existing TLS session.

THIS COMMAND "MLSD" IS WHERE THE TIMEOUT ERROR IS HAPPENING.
IT IS ASSIGNED IN THE CLIENT in ftp.go, line 619, AND ERROS WHEN ISSUED TO THE SERVER,
BUT IN FILEZILLA IT WORKS FINE.

Command:	MLSD
Trace:	tls_layer_impl::on_read()
Trace:	CFtpControlSocket::OnReceive()
Response:	150 Opening BINARY mode data connection for MLSD /.
Trace:	CFtpRawTransferOpData::ParseResponse() in state 4
Trace:	CControlSocket::SendNextCommand()
Trace:	CFtpRawTransferOpData::Send() in state 5
Trace:	tls_layer_impl::on_send()
Trace:	tls_layer_impl::continue_handshake()
Trace:	TLS handshake: About to send CLIENT HELLO
Trace:	TLS handshake: Sent CLIENT HELLO
Trace:	tls_layer_impl::on_read()
Trace:	tls_layer_impl::continue_handshake()
Trace:	TLS handshake: Received SERVER HELLO
Trace:	TLS handshake: Processed SERVER HELLO
Trace:	TLS handshake: Received FINISHED
Trace:	TLS handshake: Processed FINISHED
Trace:	TLS handshake: About to send FINISHED
Trace:	TLS handshake: Sent FINISHED
Trace:	TLS Handshake successful
Trace:	TLS Session resumed
Trace:	Protocol: TLS1.2, Key exchange: ECDHE-SECP256R1, Cipher: AES-256-GCM, MAC: AEAD
Trace:	tls_layer_impl::verify_certificate()
Trace:	CTransferSocket::OnConnect
Trace:	CTransferSocket::OnReceive(), m_transferMode=0
Trace:	tls_layer_impl::on_read()
Trace:	CTransferSocket::OnReceive(), m_transferMode=0
Trace:	tls_layer_impl::on_read()
Trace:	CFtpControlSocket::OnReceive()
Response:	226 Transfer complete. 136 bytes transferred. 136 bps.
Trace:	CFtpRawTransferOpData::ParseResponse() in state 5
Trace:	CControlSocket::SendNextCommand()
Trace:	CFtpRawTransferOpData::Send() in state 8
Trace:	tls_layer_impl::on_read()
Trace:	CTransferSocket::OnReceive(), m_transferMode=0
Trace:	CTransferSocket::TransferEnd(1)
Trace:	tls_layer_impl::shutdown()
Trace:	tls_layer_impl::continue_shutdown()
Trace:	CFtpControlSocket::TransferEnd()
Trace:	CFtpControlSocket::ResetOperation(0)
Trace:	CControlSocket::ResetOperation(0)
Trace:	CFtpRawTransferOpData::Reset(0) in state 8
Trace:	CFtpListOpData::SubcommandResult(0) in state 3
Trace:	CFtpControlSocket::ResetOperation(0)
Trace:	CControlSocket::ResetOperation(0)
Trace:	CFtpListOpData::Reset(0) in state 3
Status:	Directory listing of "/" successful
Trace:	CFileZillaEnginePrivate::ResetOperation(0)
Trace:	CControlSocket::SendNextCommand()
Trace:	CFtpListOpData::Send() in state 0
Status:	Retrieving directory listing of "/MY DIRECTORY"...
Trace:	CFtpChangeDirOpData::Send() in state 0
Trace:	CFtpChangeDirOpData::Send() in state 2
Command:	CWD /MY DIRECTORY
Trace:	tls_layer_impl::on_read()
Trace:	CFtpControlSocket::OnReceive()
Response:	250 Folder changed to "/MY DIRECTORY".
Trace:	CFtpChangeDirOpData::ParseResponse() in state 2
Trace:	CFtpControlSocket::ResetOperation(0)
Trace:	CControlSocket::ResetOperation(0)
Trace:	CFtpChangeDirOpData::Reset(0) in state 2
Trace:	CFtpListOpData::SubcommandResult(0) in state 1
Trace:	CControlSocket::SendNextCommand()
Trace:	CFtpListOpData::Send() in state 2
Trace:	CFtpRawTransferOpData::Send() in state 0
Trace:	CFtpRawTransferOpData::Send() in state 2
Command:	PASV
Trace:	tls_layer_impl::on_read()
Trace:	CFtpControlSocket::OnReceive()
Response:	227 Entering Passive Mode (74,51,209,105,82,18).
Trace:	CFtpRawTransferOpData::ParseResponse() in state 2
Trace:	CControlSocket::SendNextCommand()
Trace:	CFtpRawTransferOpData::Send() in state 4
Trace:	Binding data connection source IP to control connection source IP XXX.XXX.XXX.XXX
Trace:	tls_layer_impl::client_handshake()
Trace:	Trying to resume existing TLS session.
Command:	MLSD
Trace:	tls_layer_impl::on_send()
Trace:	tls_layer_impl::continue_handshake()
Trace:	TLS handshake: About to send CLIENT HELLO
Trace:	TLS handshake: Sent CLIENT HELLO
Trace:	tls_layer_impl::on_read()
Trace:	CFtpControlSocket::OnReceive()
Response:	150 Opening BINARY mode data connection for MLSD /MY DIRECTORY.
Trace:	CFtpRawTransferOpData::ParseResponse() in state 4
Trace:	CControlSocket::SendNextCommand()
Trace:	CFtpRawTransferOpData::Send() in state 5
Trace:	tls_layer_impl::on_read()
Trace:	tls_layer_impl::continue_handshake()
Trace:	TLS handshake: Received SERVER HELLO
Trace:	TLS handshake: Processed SERVER HELLO
Trace:	TLS handshake: Received FINISHED
Trace:	TLS handshake: Processed FINISHED
Trace:	TLS handshake: About to send FINISHED
Trace:	TLS handshake: Sent FINISHED
Trace:	TLS Handshake successful
Trace:	TLS Session resumed
Trace:	Protocol: TLS1.2, Key exchange: ECDHE-SECP256R1, Cipher: AES-256-GCM, MAC: AEAD
Trace:	tls_layer_impl::verify_certificate()
Trace:	CTransferSocket::OnConnect
Trace:	CTransferSocket::OnReceive(), m_transferMode=0
Trace:	tls_layer_impl::on_read()
Trace:	CTransferSocket::OnReceive(), m_transferMode=0
Trace:	tls_layer_impl::on_read()
Trace:	CTransferSocket::OnReceive(), m_transferMode=0
Trace:	CTransferSocket::TransferEnd(1)
Trace:	tls_layer_impl::shutdown()
Trace:	tls_layer_impl::continue_shutdown()
Trace:	CFtpControlSocket::TransferEnd()
Trace:	tls_layer_impl::on_read()
Trace:	CFtpControlSocket::OnReceive()
Response:	226 Transfer complete. 2889 bytes transferred. 2889 bps.
Trace:	CFtpRawTransferOpData::ParseResponse() in state 7
Trace:	CFtpControlSocket::ResetOperation(0)
Trace:	CControlSocket::ResetOperation(0)
Trace:	CFtpRawTransferOpData::Reset(0) in state 7
Trace:	CFtpListOpData::SubcommandResult(0) in state 3
Trace:	CFtpControlSocket::ResetOperation(0)
Trace:	CControlSocket::ResetOperation(0)
Trace:	CFtpListOpData::Reset(0) in state 3
Status:	Directory listing of "/MY DIRECTORY" successful

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

Salicorne · 2022-04-01T07:37:03Z

I observed the same behaviour using the latest version (v0.0.0-20220310202011-d2c44e311e78), when calling List(), Retr() or Stor() the connection hangs after entering passive mode with "Context deadline exceeded".
I have however been able to use the library as expected using a previous version (v0.0.0-20220301011324-fed5bc26b7fa), could you try to downgrade and report your results ?

jpfluger · 2022-04-01T13:55:38Z

Yes! The downgrade worked! Thank you so much @Salicorne!!! 👏 👍 💯

stale · 2022-05-02T06:50:36Z

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

l-austenfeld · 2022-05-10T11:40:17Z

This patch seems to be the breaking change:
212daf2#diff-b2d3016bca163c486dfe9176211bbbf072c63d29219216c27df56b5b2e252140R523

From this diagram (https://www.rfc-editor.org/rfc/rfc4217#section-12.7) it looks like the client is only supposed to open the data connection and do the TLS handshake after issuing the command requiring the connection. Currently the client opens the connection and performs the handshake before the command.

The old code did not perform the handshake when opening the connection, instead the handshake was performed lazily on first use.

tetsuyanh · 2022-08-10T13:21:11Z

I also have same problem.
I've tried to store very small file, but timeout error.
I set timeout 20 seconds enough time.

I cannot fix this by old version(v0.0.0-20220301011324-fed5bc26b7fa).
#253 (comment)

220 Welcome to Integration system.
AUTH TLS
234 Proceed with negotiation.
USER sys2074
331 Please specify the password.
PASS A7NpFZU/KP
230 Login successful.
FEAT
211-Features:
 AUTH TLS
 EPRT
 EPSV
 MDTM
 PASV
 PBSZ
 PROT
 REST STREAM
 SIZE
 TVFS
 UTF8
211 End
TYPE I
200 Switching to Binary mode.
OPTS UTF8 ON
200 Always in UTF8 mode.
PBSZ 0
200 PBSZ set to 0.
PROT P
200 PROT now Private.
CWD /kw-if-f20242
250 Directory successfully changed.
PASV
227 Entering Passive Mode (10,157,140,43,254,71).
ERRO[0022] store failed: Stor: dial tcp 10.157.140.43:65095: i/o timeout
exit status 1

dhait · 2022-08-12T18:37:17Z

I observed the same behaviour using the latest version (v0.0.0-20220310202011-d2c44e311e78), when calling List(), Retr() or Stor() the connection hangs after entering passive mode with "Context deadline exceeded". I have however been able to use the library as expected using a previous version (v0.0.0-20220301011324-fed5bc26b7fa), could you try to downgrade and report your results ?

I can confirm that the downgrade solved my problem as well (hanging on PASV in FTPS). So whatever you changed, it messed up the Passive mode.

swamy2712 · 2022-09-14T12:18:53Z

I'm also faced with same problem. Is it safe to downgrade to previous version ? Any timeline or dates on fix for this is much appreciated.

knmoorthy · 2022-09-15T17:17:39Z

I am also facing similar issue with ftps. please fix this asap or please let us know timeline if any

fraserdarwent · 2022-10-04T13:01:12Z

Also encountered this. Using a previous version as suggested works fine.

pwnb0y · 2022-11-29T16:54:32Z

me too

BrianLeishman · 2022-12-22T21:51:39Z

+1

l-austenfeld · 2023-10-20T11:11:36Z

Looks like this was fixed in #283

jpfluger added the defect The code does not work as intended label Mar 31, 2022

stale bot added the stale Will auto close after 14 days label May 2, 2022

jlaffaye added accepted Accepted issue and removed stale Will auto close after 14 days labels May 4, 2022

dhait mentioned this issue Sep 5, 2022

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

Closed

Aoang mentioned this issue Feb 21, 2023

FTP no support FTPS alist-org/alist#3554

Closed

4 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Timeout when using ftps to invoke .List and .NameList (TLS) #253

Timeout when using ftps to invoke .List and .NameList (TLS) #253

jpfluger commented Mar 31, 2022 •

edited

Loading

Salicorne commented Apr 1, 2022

jpfluger commented Apr 1, 2022

stale bot commented May 2, 2022

l-austenfeld commented May 10, 2022

tetsuyanh commented Aug 10, 2022

dhait commented Aug 12, 2022

swamy2712 commented Sep 14, 2022

knmoorthy commented Sep 15, 2022

fraserdarwent commented Oct 4, 2022

pwnb0y commented Nov 29, 2022

BrianLeishman commented Dec 22, 2022

l-austenfeld commented Oct 20, 2023

Timeout when using ftps to invoke .List and .NameList (TLS) #253

Timeout when using ftps to invoke .List and .NameList (TLS) #253

Comments

jpfluger commented Mar 31, 2022 • edited Loading

Salicorne commented Apr 1, 2022

jpfluger commented Apr 1, 2022

stale bot commented May 2, 2022

l-austenfeld commented May 10, 2022

tetsuyanh commented Aug 10, 2022

dhait commented Aug 12, 2022

swamy2712 commented Sep 14, 2022

knmoorthy commented Sep 15, 2022

fraserdarwent commented Oct 4, 2022

pwnb0y commented Nov 29, 2022

BrianLeishman commented Dec 22, 2022

l-austenfeld commented Oct 20, 2023

jpfluger commented Mar 31, 2022 •

edited

Loading