jlaffaye
Timeout when using ftps to invoke .List and .NameList (TLS)
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
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 ?
Yes! The downgrade worked! Thank you so much @Salicorne!!! :clap: :+1: :100:
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.
![stale[bot] avatar](https://avatars.githubusercontent.com/in/1724?v=4 "Published by a pub.dev verified publisher"){kind=small}
This patch seems to be the breaking change: https://github.com/jlaffaye/ftp/commit/212daf295f0e6ae44131ea12ee353a13fca71091#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.
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). https://github.com/jlaffaye/ftp/issues/253#issuecomment-1085537235
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
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.
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.
I am also facing similar issue with ftps. please fix this asap or please let us know timeline if any
Also encountered this. Using a previous version as suggested works fine.
