Timeout on listing
Posted: 2021-05-24 23:40
Hello Support,
I have a similar issue making a connection to an external server. The connection occurs but cannot list the remote directory. Receive a timeout error.
Version 3.54.1
The Connection/FTP/Passive mode option to "Use the servers external IP address instead" is selected.
I've extracted the relevant section of the error log showing going into passive mode and using the server peer address.
Response: 227 Entering Passive Mode (10,110,0,254,35,66).
Trace: CFtpRawTransferOpData::ParseResponse() in state 2
Status: Server sent passive reply with unroutable address. Using server address instead.
Trace: Reply: 10.110.0.254, peer: xxx.110.123.90
Trace: CControlSocket::SendNextCommand()
Trace: CFtpRawTransferOpData::Send() in state 4
Trace: Binding data connection source IP to control connection source IP xxx.168.1.71
Trace: tls_layer_impl::client_handshake()
Trace: Trying to resume existing TLS session.
Command: LIST
#Error: Connection timed out after 20 seconds of inactivity
FULL LOG FROM CONNECTING
Status: Connecting to xxx.110.123.90:50111...
Status: Connection established, waiting for welcome message...
Trace: CFtpControlSocket::OnReceive()
Response: 220 Welcome to VPPS FTP service.
Trace: CFtpLogonOpData::ParseResponse() in state 1
Trace: CControlSocket::SendNextCommand()
Trace: CFtpLogonOpData::Send() in state 2
Command: AUTH TLS
Trace: CFtpControlSocket::OnReceive()
Response: 234 Proceed with negotiation.
Trace: CFtpLogonOpData::ParseResponse() in state 2
Status: Initializing TLS...
Trace: tls_layer_impl::client_handshake()
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_send()
Trace: tls_layer_impl::continue_handshake()
Trace: tls_layer_impl::on_read()
Trace: tls_layer_impl::continue_handshake()
Trace: tls_layer_impl::on_read()
Trace: tls_layer_impl::continue_handshake()
Trace: TLS handshake: Received HELLO RETRY REQUEST
Trace: TLS handshake: Processed HELLO RETRY REQUEST
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 ENCRYPTED EXTENSIONS
Trace: TLS handshake: Processed ENCRYPTED EXTENSIONS
Trace: TLS handshake: Received CERTIFICATE REQUEST
Trace: TLS handshake: Processed CERTIFICATE REQUEST
Trace: TLS handshake: Received CERTIFICATE
Trace: TLS handshake: Processed CERTIFICATE
Trace: TLS handshake: Received CERTIFICATE VERIFY
Trace: TLS handshake: Processed CERTIFICATE VERIFY
Trace: TLS handshake: Received FINISHED
Trace: TLS handshake: Processed FINISHED
Trace: TLS handshake: About to send CERTIFICATE
Trace: TLS handshake: Sent CERTIFICATE
Trace: TLS handshake: About to send FINISHED
Trace: TLS handshake: Sent FINISHED
Trace: TLS Handshake successful
Trace: Protocol: TLS1.3, Key exchange: ECDHE-SECP256R1-RSA-PSS-RSAE-SHA384, Cipher: AES-256-GCM, MAC: AEAD
Trace: tls_layer_impl::verify_certificate()
Status: Verifying certificate...
Trace: CFtpControlSocket::SetAsyncRequestReply
Status: TLS connection established.
Trace: CControlSocket::SendNextCommand()
Trace: CFtpLogonOpData::Send() in state 6
Command: USER virtualpps
Trace: CFtpControlSocket::OnReceive()
Trace: TLS handshake: Received NEW SESSION TICKET
Trace: TLS handshake: Processed NEW SESSION TICKET
Trace: gnutls_record_recv returned spurious EAGAIN
Trace: TLS handshake: Received NEW SESSION TICKET
Trace: TLS handshake: Processed NEW SESSION TICKET
Trace: gnutls_record_recv returned spurious EAGAIN
Trace: tls_layer_impl::on_read()
Trace: CFtpControlSocket::OnReceive()
Response: 331 Please specify the password.
Trace: CFtpLogonOpData::ParseResponse() in state 6
Trace: CControlSocket::SendNextCommand()
Trace: CFtpLogonOpData::Send() in state 6
Command: PASS *********
Trace: tls_layer_impl::on_read()
Trace: CFtpControlSocket::OnReceive()
Response: 230 Login successful.
Trace: CFtpLogonOpData::ParseResponse() in state 6
Status: Server does not support non-ASCII characters.
Trace: CControlSocket::SendNextCommand()
Trace: CFtpLogonOpData::Send() in state 11
Command: PBSZ 0
Trace: tls_layer_impl::on_read()
Trace: CFtpControlSocket::OnReceive()
Response: 200 PBSZ set to 0.
Trace: CFtpLogonOpData::ParseResponse() in state 11
Trace: CControlSocket::SendNextCommand()
Trace: CFtpLogonOpData::Send() in state 12
Command: PROT P
Trace: tls_layer_impl::on_read()
Trace: CFtpControlSocket::OnReceive()
Response: 200 PROT now Private.
Trace: CFtpLogonOpData::ParseResponse() in state 12
Status: Logged in
Trace: Measured latency of 50 ms
Trace: CFtpControlSocket::ResetOperation(0)
Trace: CControlSocket::ResetOperation(0)
Trace: CFtpLogonOpData::Reset(0) in state 15
Trace: CFileZillaEnginePrivate::ResetOperation(0)
Trace: CControlSocket::SendNextCommand()
Trace: CFtpListOpData::Send() in state 0
Status: Retrieving directory listing...
Trace: CFtpChangeDirOpData::Send() in state 0
Trace: CFtpChangeDirOpData::Send() in state 1
Command: PWD
Trace: tls_layer_impl::on_read()
Trace: CFtpControlSocket::OnReceive()
Response: 257 "/" is the current directory
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 Switching to Binary mode.
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 (10,110,0,254,35,66).
Trace: CFtpRawTransferOpData::ParseResponse() in state 2
Status: Server sent passive reply with unroutable address. Using server address instead.
Trace: Reply: 10.110.0.254, peer: xxx.110.123.90
Trace: CControlSocket::SendNextCommand()
Trace: CFtpRawTransferOpData::Send() in state 4
Trace: Binding data connection source IP to control connection source IP xxx.168.1.71
Trace: tls_layer_impl::client_handshake()
Trace: Trying to resume existing TLS session.
Command: LIST
#Error: Connection timed out after 20 seconds of inactivity
Trace: CFtpControlSocket::ResetOperation(2114)
Trace: CControlSocket::ResetOperation(2114)
Trace: CFtpRawTransferOpData::Reset(2114) in state 4
Trace: CFtpControlSocket::ResetOperation(2114)
Trace: CControlSocket::ResetOperation(2114)
Trace: CFtpListOpData::Reset(2114) in state 3
Error: Failed to retrieve directory listing
Status: Disconnected from server
I have a similar issue making a connection to an external server. The connection occurs but cannot list the remote directory. Receive a timeout error.
Version 3.54.1
The Connection/FTP/Passive mode option to "Use the servers external IP address instead" is selected.
I've extracted the relevant section of the error log showing going into passive mode and using the server peer address.
Response: 227 Entering Passive Mode (10,110,0,254,35,66).
Trace: CFtpRawTransferOpData::ParseResponse() in state 2
Status: Server sent passive reply with unroutable address. Using server address instead.
Trace: Reply: 10.110.0.254, peer: xxx.110.123.90
Trace: CControlSocket::SendNextCommand()
Trace: CFtpRawTransferOpData::Send() in state 4
Trace: Binding data connection source IP to control connection source IP xxx.168.1.71
Trace: tls_layer_impl::client_handshake()
Trace: Trying to resume existing TLS session.
Command: LIST
#Error: Connection timed out after 20 seconds of inactivity
FULL LOG FROM CONNECTING
Status: Connecting to xxx.110.123.90:50111...
Status: Connection established, waiting for welcome message...
Trace: CFtpControlSocket::OnReceive()
Response: 220 Welcome to VPPS FTP service.
Trace: CFtpLogonOpData::ParseResponse() in state 1
Trace: CControlSocket::SendNextCommand()
Trace: CFtpLogonOpData::Send() in state 2
Command: AUTH TLS
Trace: CFtpControlSocket::OnReceive()
Response: 234 Proceed with negotiation.
Trace: CFtpLogonOpData::ParseResponse() in state 2
Status: Initializing TLS...
Trace: tls_layer_impl::client_handshake()
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_send()
Trace: tls_layer_impl::continue_handshake()
Trace: tls_layer_impl::on_read()
Trace: tls_layer_impl::continue_handshake()
Trace: tls_layer_impl::on_read()
Trace: tls_layer_impl::continue_handshake()
Trace: TLS handshake: Received HELLO RETRY REQUEST
Trace: TLS handshake: Processed HELLO RETRY REQUEST
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 ENCRYPTED EXTENSIONS
Trace: TLS handshake: Processed ENCRYPTED EXTENSIONS
Trace: TLS handshake: Received CERTIFICATE REQUEST
Trace: TLS handshake: Processed CERTIFICATE REQUEST
Trace: TLS handshake: Received CERTIFICATE
Trace: TLS handshake: Processed CERTIFICATE
Trace: TLS handshake: Received CERTIFICATE VERIFY
Trace: TLS handshake: Processed CERTIFICATE VERIFY
Trace: TLS handshake: Received FINISHED
Trace: TLS handshake: Processed FINISHED
Trace: TLS handshake: About to send CERTIFICATE
Trace: TLS handshake: Sent CERTIFICATE
Trace: TLS handshake: About to send FINISHED
Trace: TLS handshake: Sent FINISHED
Trace: TLS Handshake successful
Trace: Protocol: TLS1.3, Key exchange: ECDHE-SECP256R1-RSA-PSS-RSAE-SHA384, Cipher: AES-256-GCM, MAC: AEAD
Trace: tls_layer_impl::verify_certificate()
Status: Verifying certificate...
Trace: CFtpControlSocket::SetAsyncRequestReply
Status: TLS connection established.
Trace: CControlSocket::SendNextCommand()
Trace: CFtpLogonOpData::Send() in state 6
Command: USER virtualpps
Trace: CFtpControlSocket::OnReceive()
Trace: TLS handshake: Received NEW SESSION TICKET
Trace: TLS handshake: Processed NEW SESSION TICKET
Trace: gnutls_record_recv returned spurious EAGAIN
Trace: TLS handshake: Received NEW SESSION TICKET
Trace: TLS handshake: Processed NEW SESSION TICKET
Trace: gnutls_record_recv returned spurious EAGAIN
Trace: tls_layer_impl::on_read()
Trace: CFtpControlSocket::OnReceive()
Response: 331 Please specify the password.
Trace: CFtpLogonOpData::ParseResponse() in state 6
Trace: CControlSocket::SendNextCommand()
Trace: CFtpLogonOpData::Send() in state 6
Command: PASS *********
Trace: tls_layer_impl::on_read()
Trace: CFtpControlSocket::OnReceive()
Response: 230 Login successful.
Trace: CFtpLogonOpData::ParseResponse() in state 6
Status: Server does not support non-ASCII characters.
Trace: CControlSocket::SendNextCommand()
Trace: CFtpLogonOpData::Send() in state 11
Command: PBSZ 0
Trace: tls_layer_impl::on_read()
Trace: CFtpControlSocket::OnReceive()
Response: 200 PBSZ set to 0.
Trace: CFtpLogonOpData::ParseResponse() in state 11
Trace: CControlSocket::SendNextCommand()
Trace: CFtpLogonOpData::Send() in state 12
Command: PROT P
Trace: tls_layer_impl::on_read()
Trace: CFtpControlSocket::OnReceive()
Response: 200 PROT now Private.
Trace: CFtpLogonOpData::ParseResponse() in state 12
Status: Logged in
Trace: Measured latency of 50 ms
Trace: CFtpControlSocket::ResetOperation(0)
Trace: CControlSocket::ResetOperation(0)
Trace: CFtpLogonOpData::Reset(0) in state 15
Trace: CFileZillaEnginePrivate::ResetOperation(0)
Trace: CControlSocket::SendNextCommand()
Trace: CFtpListOpData::Send() in state 0
Status: Retrieving directory listing...
Trace: CFtpChangeDirOpData::Send() in state 0
Trace: CFtpChangeDirOpData::Send() in state 1
Command: PWD
Trace: tls_layer_impl::on_read()
Trace: CFtpControlSocket::OnReceive()
Response: 257 "/" is the current directory
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 Switching to Binary mode.
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 (10,110,0,254,35,66).
Trace: CFtpRawTransferOpData::ParseResponse() in state 2
Status: Server sent passive reply with unroutable address. Using server address instead.
Trace: Reply: 10.110.0.254, peer: xxx.110.123.90
Trace: CControlSocket::SendNextCommand()
Trace: CFtpRawTransferOpData::Send() in state 4
Trace: Binding data connection source IP to control connection source IP xxx.168.1.71
Trace: tls_layer_impl::client_handshake()
Trace: Trying to resume existing TLS session.
Command: LIST
#Error: Connection timed out after 20 seconds of inactivity
Trace: CFtpControlSocket::ResetOperation(2114)
Trace: CControlSocket::ResetOperation(2114)
Trace: CFtpRawTransferOpData::Reset(2114) in state 4
Trace: CFtpControlSocket::ResetOperation(2114)
Trace: CControlSocket::ResetOperation(2114)
Trace: CFtpListOpData::Reset(2114) in state 3
Error: Failed to retrieve directory listing
Status: Disconnected from server