FileZilla Forums

I'm running apache ftpserver 1.1.1 (the binary distribution, no custom code) on localhost with Java 11 to get TLSv1.3 support. FileZilla makes the control connection without any problem, but fails making the data connection. I've noticed this discrepancy in the debug level logs for FileZilla between the 2 connections:

10:01:27 Trace: Protocol: TLS1.3, Key exchange: ECDHE-SECP384R1-RSA-PSS-RSAE-SHA384, Cipher: AES-256-GCM, MAC: AEAD
10:01:28 Trace: Protocol: TLS1.3, Key exchange: unknown, Cipher: AES-256-GCM, MAC: AEAD

WinSCP works without any problems using TLSv1.3. If I run ftpserver with Java 8, then FileZilla has no problems using TLSv1.2 - the problem is only FileZilla using TLSv1.3.

If the data connection is a resumed session (which it should be for security reasons) there is no key exchange.

Which version of FileZilla are you using?

Also, please post the complete contents of the message log.

v3.49.1

10:01:27 Trace: CControlSocket::SendNextCommand()
10:01:27 Trace: CFtpLogonOpData::Send() in state 0
10:01:27 Status: Resolving address of dev.XXXXXX.com
10:01:27 Status: Connecting to 127.0.0.1:2121...
10:01:27 Status: Connection established, waiting for welcome message...
10:01:27 Trace: CFtpControlSocket::OnReceive()
10:01:27 Response: 220 Service ready for new user.
10:01:27 Trace: CFtpLogonOpData::ParseResponse() in state 1
10:01:27 Trace: CControlSocket::SendNextCommand()
10:01:27 Trace: CFtpLogonOpData::Send() in state 2
10:01:27 Command: AUTH TLS
10:01:27 Trace: CFtpControlSocket::OnReceive()
10:01:27 Response: 234 Command AUTH okay; starting TLS connection.
10:01:27 Trace: CFtpLogonOpData::ParseResponse() in state 2
10:01:27 Status: Initializing TLS...
10:01:27 Trace: tls_layer_impl::client_handshake()
10:01:27 Trace: tls_layer_impl::continue_handshake()
10:01:27 Trace: TLS handshake: About to send CLIENT HELLO
10:01:27 Trace: TLS handshake: Sent CLIENT HELLO
10:01:27 Trace: tls_layer_impl::on_send()
10:01:27 Trace: tls_layer_impl::continue_handshake()
10:01:27 Trace: tls_layer_impl::on_read()
10:01:27 Trace: tls_layer_impl::continue_handshake()
10:01:27 Trace: tls_layer_impl::on_read()
10:01:27 Trace: tls_layer_impl::continue_handshake()
10:01:27 Trace: TLS handshake: Received SERVER HELLO
10:01:27 Trace: TLS handshake: Processed SERVER HELLO
10:01:27 Trace: TLS handshake: Received ENCRYPTED EXTENSIONS
10:01:27 Trace: TLS handshake: Processed ENCRYPTED EXTENSIONS
10:01:27 Trace: TLS handshake: Received CERTIFICATE
10:01:27 Trace: TLS handshake: Processed CERTIFICATE
10:01:27 Trace: TLS handshake: Received CERTIFICATE VERIFY
10:01:27 Trace: TLS handshake: Processed CERTIFICATE VERIFY
10:01:27 Trace: TLS handshake: Received FINISHED
10:01:27 Trace: TLS handshake: Processed FINISHED
10:01:27 Trace: TLS handshake: About to send FINISHED
10:01:27 Trace: TLS handshake: Sent FINISHED
10:01:27 Trace: TLS Handshake successful
10:01:27 Trace: Protocol: TLS1.3, Key exchange: ECDHE-SECP384R1-RSA-PSS-RSAE-SHA384, Cipher: AES-256-GCM, MAC: AEAD
10:01:27 Trace: tls_layer_impl::verify_certificate()
10:01:27 Status: Verifying certificate...
10:01:28 Trace: CFtpControlSocket::SetAsyncRequestReply
10:01:28 Status: TLS connection established.
10:01:28 Trace: CControlSocket::SendNextCommand()
10:01:28 Trace: CFtpLogonOpData::Send() in state 6
10:01:28 Command: USER admin
10:01:28 Trace: CFtpControlSocket::OnReceive()
10:01:28 Trace: TLS handshake: Received NEW SESSION TICKET
10:01:28 Trace: TLS handshake: Processed NEW SESSION TICKET
10:01:28 Trace: gnutls_record_recv returned spurious EAGAIN
10:01:28 Trace: tls_layer_impl::on_read()
10:01:28 Trace: CFtpControlSocket::OnReceive()
10:01:28 Response: 331 User name okay, need password for admin.
10:01:28 Trace: CFtpLogonOpData::ParseResponse() in state 6
10:01:28 Trace: CControlSocket::SendNextCommand()
10:01:28 Trace: CFtpLogonOpData::Send() in state 6
10:01:28 Command: PASS *****
10:01:28 Trace: tls_layer_impl::on_read()
10:01:28 Trace: CFtpControlSocket::OnReceive()
10:01:28 Response: 230 User logged in, proceed.
10:01:28 Trace: CFtpLogonOpData::ParseResponse() in state 6
10:01:28 Trace: CControlSocket::SendNextCommand()
10:01:28 Trace: CFtpLogonOpData::Send() in state 10
10:01:28 Command: OPTS UTF8 ON
10:01:28 Trace: tls_layer_impl::on_read()
10:01:28 Trace: CFtpControlSocket::OnReceive()
10:01:28 Response: 200 Command OPTS okay.
10:01:28 Trace: CFtpLogonOpData::ParseResponse() in state 10
10:01:28 Trace: CControlSocket::SendNextCommand()
10:01:28 Trace: CFtpLogonOpData::Send() in state 11
10:01:28 Command: PBSZ 0
10:01:28 Trace: tls_layer_impl::on_read()
10:01:28 Trace: CFtpControlSocket::OnReceive()
10:01:28 Response: 200 Command PBSZ okay.
10:01:28 Trace: CFtpLogonOpData::ParseResponse() in state 11
10:01:28 Trace: CControlSocket::SendNextCommand()
10:01:28 Trace: CFtpLogonOpData::Send() in state 12
10:01:28 Command: PROT P
10:01:28 Trace: tls_layer_impl::on_read()
10:01:28 Trace: CFtpControlSocket::OnReceive()
10:01:28 Response: 200 Command PROT okay.
10:01:28 Trace: CFtpLogonOpData::ParseResponse() in state 12
10:01:28 Trace: CControlSocket::SendNextCommand()
10:01:28 Trace: CFtpLogonOpData::Send() in state 13
10:01:28 Command: OPTS MLST size;modify;type;
10:01:28 Trace: tls_layer_impl::on_read()
10:01:28 Trace: CFtpControlSocket::OnReceive()
10:01:28 Response: 200 Command OPTS okay.
10:01:28 Trace: CFtpLogonOpData::ParseResponse() in state 13
10:01:28 Status: Logged in
10:01:28 Trace: Measured latency of 0 ms
10:01:28 Trace: CFtpControlSocket::ResetOperation(0)
10:01:28 Trace: CControlSocket::ResetOperation(0)
10:01:28 Trace: CFtpLogonOpData::Reset(0) in state 15
10:01:28 Trace: CFileZillaEnginePrivate::ResetOperation(0)
10:01:28 Trace: CControlSocket::SendNextCommand()
10:01:28 Trace: CFtpListOpData::Send() in state 0
10:01:28 Status: Retrieving directory listing...
10:01:28 Trace: CFtpChangeDirOpData::Send() in state 0
10:01:28 Trace: CFtpChangeDirOpData::Send() in state 1
10:01:28 Command: PWD
10:01:28 Trace: tls_layer_impl::on_read()
10:01:28 Trace: CFtpControlSocket::OnReceive()
10:01:28 Response: 257 "/" is current directory.
10:01:28 Trace: CFtpChangeDirOpData::ParseResponse() in state 1
10:01:28 Trace: CFtpControlSocket::ResetOperation(0)
10:01:28 Trace: CControlSocket::ResetOperation(0)
10:01:28 Trace: CFtpChangeDirOpData::Reset(0) in state 1
10:01:28 Trace: CFtpListOpData::SubcommandResult(0) in state 1
10:01:28 Trace: CControlSocket::SendNextCommand()
10:01:28 Trace: CFtpListOpData::Send() in state 2
10:01:28 Trace: CFtpRawTransferOpData::Send() in state 0
10:01:28 Trace: CFtpRawTransferOpData::Send() in state 1
10:01:28 Command: TYPE I
10:01:28 Trace: tls_layer_impl::on_read()
10:01:28 Trace: CFtpControlSocket::OnReceive()
10:01:28 Response: 200 Command TYPE okay.
10:01:28 Trace: CFtpRawTransferOpData::ParseResponse() in state 1
10:01:28 Trace: CControlSocket::SendNextCommand()
10:01:28 Trace: CFtpRawTransferOpData::Send() in state 2
10:01:28 Command: PASV
10:01:28 Trace: tls_layer_impl::on_read()
10:01:28 Trace: CFtpControlSocket::OnReceive()
10:01:28 Response: 227 Entering Passive Mode (127,0,0,1,255,103)
10:01:28 Trace: CFtpRawTransferOpData::ParseResponse() in state 2
10:01:28 Trace: CControlSocket::SendNextCommand()
10:01:28 Trace: CFtpRawTransferOpData::Send() in state 4
10:01:28 Trace: Binding data connection source IP to control connection source IP 127.0.0.1
10:01:28 Trace: tls_layer_impl::client_handshake()
10:01:28 Trace: Trying to resume existing TLS session.
10:01:28 Command: MLSD
10:01:28 Trace: tls_layer_impl::on_send()
10:01:28 Trace: tls_layer_impl::continue_handshake()
10:01:28 Trace: TLS handshake: About to send CLIENT HELLO
10:01:28 Trace: TLS handshake: Sent CLIENT HELLO
10:01:28 Trace: tls_layer_impl::on_read()
10:01:28 Trace: CFtpControlSocket::OnReceive()
10:01:28 Response: 150 File status okay; about to open data connection.
10:01:28 Trace: CFtpRawTransferOpData::ParseResponse() in state 4
10:01:28 Trace: CControlSocket::SendNextCommand()
10:01:28 Trace: CFtpRawTransferOpData::Send() in state 5
10:01:28 Trace: tls_layer_impl::on_read()
10:01:28 Trace: tls_layer_impl::continue_handshake()
10:01:28 Trace: TLS handshake: Received SERVER HELLO
10:01:28 Trace: TLS handshake: Processed SERVER HELLO
10:01:28 Trace: tls_layer_impl::on_read()
10:01:28 Trace: tls_layer_impl::continue_handshake()
10:01:28 Trace: TLS handshake: Received ENCRYPTED EXTENSIONS
10:01:28 Trace: TLS handshake: Processed ENCRYPTED EXTENSIONS
10:01:28 Trace: tls_layer_impl::on_read()
10:01:28 Trace: tls_layer_impl::continue_handshake()
10:01:28 Trace: TLS handshake: Received FINISHED
10:01:28 Trace: TLS handshake: Processed FINISHED
10:01:28 Trace: TLS handshake: About to send FINISHED
10:01:28 Trace: TLS handshake: Sent FINISHED
10:01:28 Trace: TLS Handshake successful
10:01:28 Trace: TLS Session resumed
10:01:28 Trace: Protocol: TLS1.3, Key exchange: unknown, Cipher: AES-256-GCM, MAC: AEAD
10:01:28 Trace: tls_layer_impl::verify_certificate()
10:01:28 Trace: CTransferSocket::OnConnect
10:01:28 Trace: CTransferSocket::OnReceive(), m_transferMode=0
10:01:28 Trace: tls_layer_impl::on_read()
10:01:28 Trace: CTransferSocket::OnReceive(), m_transferMode=0
10:01:28 Trace: TLS handshake: Received NEW SESSION TICKET
10:01:28 Trace: TLS handshake: Processed NEW SESSION TICKET
10:01:28 Trace: gnutls_record_recv returned spurious EAGAIN
10:01:28 Trace: tls_layer_impl::on_read()
10:01:28 Trace: CTransferSocket::OnReceive(), m_transferMode=0
10:01:28 Trace: tls_layer_impl::failure(-12)
10:01:28 Error: Received TLS alert from the server: User canceled (90)
10:01:28 Error: Could not read from transfer socket: ECONNABORTED - Connection aborted
10:01:28 Trace: CTransferSocket::TransferEnd(3)
10:01:28 Trace: CFtpControlSocket::TransferEnd()
10:01:28 Trace: tls_layer_impl::on_read()
10:01:28 Trace: CFtpControlSocket::OnReceive()
10:01:28 Response: 226 Closing data connection.
10:01:28 Trace: CFtpRawTransferOpData::ParseResponse() in state 7
10:01:28 Trace: CFtpControlSocket::ResetOperation(2)
10:01:28 Trace: CControlSocket::ResetOperation(2)
10:01:28 Trace: CFtpRawTransferOpData::Reset(2) in state 7
10:01:28 Trace: CFtpListOpData::SubcommandResult(2) in state 3
10:01:28 Trace: CFtpControlSocket::ResetOperation(2)
10:01:28 Trace: CControlSocket::ResetOperation(2)
10:01:28 Trace: CFtpListOpData::Reset(2) in state 3
10:01:28 Error: Failed to retrieve directory listing
10:01:28 Trace: CFileZillaEnginePrivate::ResetOperation(2)

For some reason your server is sending a user_canceled alert. Check your server logs to see why the server is generating this alert and contact your server vendor for further assistance.

Did you manage to resolve this?

I'm getting the same problem with Apache ftpServer 1.1.1

Possibly to do with ssl data connection reuse as described here albeit from a client perspective rather than the server?

https://eng.wealthfront.com/2016/06/10/ ... a-7-and-8/

I have not resolved it yet. In stepping through the ftpserver code, I know that the problem happens inside the MLSD.java code on line 114 - dataConnection.transferToClient(), but I haven't yet seen anything wrong when I step through it in detail, and it's not an exception that's caught by the try/catch after it. From the ftpserver perspective, everything should have worked (and does when the client is WinSCP), it's just that FileZilla says there's a failure at this time and drops the connection. So it's either a problem with FileZilla, or it's deep within the common apache socket code which I have not looked into yet, or obviously something else that I've missed .

Does your server call shutdownOutput on the SSLSocket? For more information, read the source code of the SSLSocket class around the parts that deal with closing/shutting down the secure session in combination with the slightly different closure alert semantics in TLS1.2 and TLS1.3 specifications.

Hi all,

I'm struggling with exact same issue, same FtpServer and FileZilla versions, trying to see any issue within traffic with wireshark but no success (i'm not specialist of that kind of investigation)

Did anybody got a final explanation ?

Have you yet contacted your server vendor?