Server log with 1.0.0-rc5, where the same transaction is successful:
Code: Select all
{Thread: 3} <2021-09-15T22:22:36.793Z> [DD] [Ftp Server/Session 2] tls_layer_impl::on_read()
{Thread: 3} <2021-09-15T22:22:36.793Z> [CO] [Ftp Server/Session 2] PASV
{Thread: 3} <2021-09-15T22:22:36.793Z> [DV] [Ftp Server/Session 2] Trying: data_listen_socket_->listen(1, 55812)
{Thread: 3} <2021-09-15T22:22:36.825Z> [RE] [Ftp Server/Session 2] 227 Entering Passive Mode (10,0,0,1,218,4)
{Thread: 3} <2021-09-15T22:22:36.832Z> [DD] [Ftp Server/Session 2] tls_layer_impl::on_read()
{Thread: 3} <2021-09-15T22:22:36.832Z> [CO] [Ftp Server/Session 2] RETR ReadMe.html
{Thread: 3} <2021-09-15T22:22:36.843Z> [DV] [Ftp Server/Session 2] session::on_socket_event(): source = data listen, flag = 2, error = 0, state = -1
{Thread: 3} <2021-09-15T22:22:36.845Z> [DD] [Ftp Server/Session 2] Client wants a secure data connection.
{Thread: 3} <2021-09-15T22:22:36.845Z> [DD] [Ftp Server/Session 2] securer(1) ENTERING state = 0
{Thread: 3} <2021-09-15T22:22:36.845Z> [DD] [Ftp Server/Session 2] calling tls_layer_->set_certificate_file("C:\Program Files (x86)\FileZilla Server\BOCO~(v·0x00000006).key", "C:\Program Files (x86)\FileZilla Server\BOCO~(v·0x00000006).crt", "****")
{Thread: 3} <2021-09-15T22:22:36.849Z> [DD] [Ftp Server/Session 2] securer(1) EXITING state = 1
{Thread: 3} <2021-09-15T22:22:36.849Z> [DD] [Ftp Server/Session 2] Making the data connection secure.
{Thread: 3} <2021-09-15T22:22:36.849Z> [RE] [Ftp Server/Session 2] 150 Data transfer started
{Thread: 3} <2021-09-15T22:22:36.849Z> [DD] [Ftp Server/Session 2] ~securer(1) ENTERING state = 1
{Thread: 3} <2021-09-15T22:22:36.849Z> [DV] [Ftp Server/Session 2] tls_layer_impl::server_handshake()
{Thread: 3} <2021-09-15T22:22:36.849Z> [DV] [Ftp Server/Session 2] tls_layer_impl::continue_handshake()
{Thread: 3} <2021-09-15T22:22:36.849Z> [DD] [Ftp Server/Session 2] ~securer(1) EXITING state = 2
{Thread: 3} <2021-09-15T22:22:36.849Z> [DD] [Ftp Server/Session 2] tls_layer_impl::on_send()
{Thread: 3} <2021-09-15T22:22:36.849Z> [DV] [Ftp Server/Session 2] tls_layer_impl::continue_handshake()
{Thread: 3} <2021-09-15T22:22:36.849Z> [DD] [Ftp Server/Session 2] tls_layer_impl::on_read()
{Thread: 3} <2021-09-15T22:22:36.849Z> [DV] [Ftp Server/Session 2] tls_layer_impl::continue_handshake()
{Thread: 3} <2021-09-15T22:22:36.849Z> [DD] [Ftp Server/Session 2] TLS handshake: Received CLIENT HELLO
{Thread: 3} <2021-09-15T22:22:36.850Z> [DD] [Ftp Server/Session 2] TLS handshake: Processed CLIENT HELLO
{Thread: 3} <2021-09-15T22:22:36.850Z> [DD] [Ftp Server/Session 2] TLS handshake: About to send SERVER HELLO
{Thread: 3} <2021-09-15T22:22:36.850Z> [DD] [Ftp Server/Session 2] TLS handshake: Sent SERVER HELLO
{Thread: 3} <2021-09-15T22:22:36.852Z> [DD] [Ftp Server/Session 2] TLS handshake: About to send ENCRYPTED EXTENSIONS
{Thread: 3} <2021-09-15T22:22:36.852Z> [DD] [Ftp Server/Session 2] TLS handshake: Sent ENCRYPTED EXTENSIONS
{Thread: 3} <2021-09-15T22:22:36.852Z> [DD] [Ftp Server/Session 2] TLS handshake: About to send FINISHED
{Thread: 3} <2021-09-15T22:22:36.852Z> [DD] [Ftp Server/Session 2] TLS handshake: Sent FINISHED
{Thread: 3} <2021-09-15T22:22:36.861Z> [DD] [Ftp Server/Session 2] tls_layer_impl::on_read()
{Thread: 3} <2021-09-15T22:22:36.861Z> [DV] [Ftp Server/Session 2] tls_layer_impl::continue_handshake()
{Thread: 3} <2021-09-15T22:22:36.861Z> [DD] [Ftp Server/Session 2] TLS handshake: Received FINISHED
{Thread: 3} <2021-09-15T22:22:36.861Z> [DD] [Ftp Server/Session 2] TLS handshake: Processed FINISHED
{Thread: 3} <2021-09-15T22:22:36.861Z> [DD] [Ftp Server/Session 2] TLS handshake: About to send NEW SESSION TICKET
{Thread: 3} <2021-09-15T22:22:36.861Z> [DD] [Ftp Server/Session 2] TLS handshake: Sent NEW SESSION TICKET
{Thread: 3} <2021-09-15T22:22:36.861Z> [DD] [Ftp Server/Session 2] TLS handshake: About to send NEW SESSION TICKET
{Thread: 3} <2021-09-15T22:22:36.861Z> [DD] [Ftp Server/Session 2] TLS handshake: Sent NEW SESSION TICKET
{Thread: 3} <2021-09-15T22:22:36.862Z> [DI] [Ftp Server/Session 2] TLS Handshake successful
{Thread: 3} <2021-09-15T22:22:36.862Z> [DI] [Ftp Server/Session 2] TLS Session resumed
{Thread: 3} <2021-09-15T22:22:36.862Z> [DI] [Ftp Server/Session 2] Protocol: TLS1.3, Key exchange: unknown, Cipher: AES-256-GCM, MAC: AEAD
{Thread: 3} <2021-09-15T22:22:36.862Z> [DV] [Ftp Server/Session 2] session::on_socket_event(): source = data, flag = 2, error = 0, state = 2
{Thread: 3} <2021-09-15T22:22:36.862Z> [DD] [Ftp Server/Session 2] Client wants a secure data connection.
{Thread: 3} <2021-09-15T22:22:36.862Z> [DD] [Ftp Server/Session 2] securer(1) ENTERING state = 2
{Thread: 3} <2021-09-15T22:22:36.862Z> [DD] [Ftp Server/Session 2] securer(1) EXITING state = 3
{Thread: 3} <2021-09-15T22:22:36.862Z> [DD] [Ftp Server/Session 2] The data connection is now secure.
{Thread: 3} <2021-09-15T22:22:36.862Z> [DD] [Ftp Server/Session 2] ~securer(1) ENTERING state = 3
{Thread: 3} <2021-09-15T22:22:36.862Z> [DD] [Ftp Server/Session 2] ~securer(1) EXITING state = 3
{Thread: 3} <2021-09-15T22:22:36.862Z> [DD] [Ftp Server/Session 2] CHANNEL state is being dumped:
{Thread: 3} <2021-09-15T22:22:36.863Z> [DD] [Ftp Server/Session 2] PIPE((IN)) {
max_num_loops_ = 10
thread_safe_ = 0
variant_buffer_ = <2>
buffer_ =
adder_ = 0x0
consumer_ = 0x0
waiting_for_adder_event_ = 0
consumer_error_ = 0
adder_error_ = 0
}
{Thread: 3} <2021-09-15T22:22:36.863Z> [DD] [Ftp Server/Session 2] PIPE((OUT)) {
max_num_loops_ = 10
thread_safe_ = 0
variant_buffer_ = <2>
buffer_ =
adder_ = 0x0
consumer_ = 0x0
waiting_for_adder_event_ = 0
consumer_error_ = 0
adder_error_ = 0
}
{Thread: 3} <2021-09-15T22:22:36.866Z> [DV] [Ftp Server/Session 2] tls_layer_impl::shutdown()
{Thread: 3} <2021-09-15T22:22:36.866Z> [DV] [Ftp Server/Session 2] Postponing shutdown, send_buffer_ not empty
{Thread: 3} <2021-09-15T22:22:36.866Z> [DV] [Ftp Server/Session 2] data_socket_->shutdown() = 11
{Thread: 3} <2021-09-15T22:22:36.878Z> [DD] [Ftp Server/Session 2] tls_layer_impl::on_send()
{Thread: 3} <2021-09-15T22:22:36.879Z> [DV] [Ftp Server/Session 2] tls_layer_impl::continue_shutdown()
{Thread: 3} <2021-09-15T22:22:36.920Z> [DD] [Ftp Server/Session 2] tls_layer_impl::on_send()
{Thread: 3} <2021-09-15T22:22:36.920Z> [DV] [Ftp Server/Session 2] tls_layer_impl::continue_shutdown()
{Thread: 3} <2021-09-15T22:22:36.920Z> [DV] [Ftp Server/Session 2] session::on_socket_event(): source = data, flag = 8, error = 0, state = 4
{Thread: 3} <2021-09-15T22:22:36.920Z> [DV] [Ftp Server/Session 2] tls_layer_impl::shutdown()
{Thread: 3} <2021-09-15T22:22:36.920Z> [DV] [Ftp Server/Session 2] data_socket_->shutdown() = 0
{Thread: 3} <2021-09-15T22:22:36.920Z> [RE] [Ftp Server/Session 2] 226 Operation successful
{Thread: 3} <2021-09-15T22:22:36.921Z> [DV] [Ftp Server/Session 2] session::close_data_connection() = 1
{Thread: 2} <2021-09-15T22:22:40.305Z> [DD] [Ftp Server/Session 1] tls_layer_impl::on_read()
{Thread: 2} <2021-09-15T22:22:40.305Z> [DD] [Ftp Server/Session 1] tls_layer_impl::failure(-110)
{Thread: 2} <2021-09-15T22:22:40.305Z> [ER] [Ftp Server/Session 1] GnuTLS error -110 in gnutls_record_recv: The TLS connection was non-properly terminated.
{Thread: 2} <2021-09-15T22:22:40.305Z> [ST] [Ftp Server/Session 1] Client did not properly shut down TLS connection
{Thread: 2} <2021-09-15T22:22:40.305Z> [ER] [Ftp Server/Session 1] Control channel closed with error from source 0. Reason: ECONNABORTED - Connection aborted.
{Thread: 1} <2021-09-15T22:22:40.306Z> [ER] [Ftp Server] Session ended with error from source 0. Reason: ECONNABORTED - Connection aborted.
{Thread: 1} <2021-09-15T22:22:40.307Z> [DI] [Ftp Server/Session 1] Session 0x52ea70 with ID 1 destroyed.
Client, hope it makes sense.
Code: Select all
2021-09-16 00:22:39 4492 3 Trace: CControlSocket::SendNextCommand()
2021-09-16 00:22:39 4492 3 Trace: CFtpRawTransferOpData::Send() in state 2
2021-09-16 00:22:39 4492 3 Command: PASV
2021-09-16 00:22:39 4492 3 Trace: tls_layer_impl::on_read()
2021-09-16 00:22:39 4492 3 Trace: CFtpControlSocket::OnReceive()
2021-09-16 00:22:39 4492 3 Response: 227 Entering Passive Mode (10,0,0,1,218,4)
2021-09-16 00:22:39 4492 3 Trace: CFtpRawTransferOpData::ParseResponse() in state 2
2021-09-16 00:22:39 4492 3 Trace: CControlSocket::SendNextCommand()
2021-09-16 00:22:39 4492 3 Trace: CFtpRawTransferOpData::Send() in state 4
2021-09-16 00:22:39 4492 3 Trace: Binding data connection source IP to control connection source IP 10.0.0.45
2021-09-16 00:22:39 4492 3 Trace: tls_layer_impl::client_handshake()
2021-09-16 00:22:39 4492 3 Trace: Trying to resume existing TLS session.
2021-09-16 00:22:39 4492 3 Command: RETR ReadMe.html
2021-09-16 00:22:39 4492 3 Trace: tls_layer_impl::on_send()
2021-09-16 00:22:39 4492 3 Trace: tls_layer_impl::continue_handshake()
2021-09-16 00:22:39 4492 3 Trace: TLS handshake: About to send CLIENT HELLO
2021-09-16 00:22:39 4492 3 Trace: TLS handshake: Sent CLIENT HELLO
2021-09-16 00:22:39 4492 3 Trace: tls_layer_impl::on_read()
2021-09-16 00:22:39 4492 3 Trace: tls_layer_impl::continue_handshake()
2021-09-16 00:22:39 4492 3 Trace: TLS handshake: Received SERVER HELLO
2021-09-16 00:22:39 4492 3 Trace: TLS handshake: Processed SERVER HELLO
2021-09-16 00:22:39 4492 3 Trace: TLS handshake: Received ENCRYPTED EXTENSIONS
2021-09-16 00:22:39 4492 3 Trace: TLS handshake: Processed ENCRYPTED EXTENSIONS
2021-09-16 00:22:39 4492 3 Trace: TLS handshake: Received FINISHED
2021-09-16 00:22:39 4492 3 Trace: TLS handshake: Processed FINISHED
2021-09-16 00:22:39 4492 3 Trace: TLS handshake: About to send FINISHED
2021-09-16 00:22:39 4492 3 Trace: TLS handshake: Sent FINISHED
2021-09-16 00:22:39 4492 3 Trace: TLS Handshake successful
2021-09-16 00:22:39 4492 3 Trace: TLS Session resumed
2021-09-16 00:22:39 4492 3 Trace: Protocol: TLS1.3, Key exchange: unknown, Cipher: AES-256-GCM, MAC: AEAD
2021-09-16 00:22:39 4492 3 Trace: tls_layer_impl::verify_certificate()
2021-09-16 00:22:39 4492 3 Trace: tls_layer_impl::on_read()
2021-09-16 00:22:39 4492 3 Trace: CTransferSocket::OnConnect
2021-09-16 00:22:39 4492 3 Trace: CTransferSocket::OnReceive(), m_transferMode=2
2021-09-16 00:22:39 4492 3 Trace: CFtpControlSocket::OnReceive()
2021-09-16 00:22:39 4492 3 Response: 150 Data transfer started
2021-09-16 00:22:39 4492 3 Trace: CFtpRawTransferOpData::ParseResponse() in state 4
2021-09-16 00:22:39 4492 3 Trace: CControlSocket::SendNextCommand()
2021-09-16 00:22:39 4492 3 Trace: CFtpRawTransferOpData::Send() in state 5
2021-09-16 00:22:39 4492 3 Trace: tls_layer_impl::on_read()
2021-09-16 00:22:39 4492 3 Trace: CTransferSocket::OnReceive(), m_transferMode=2
2021-09-16 00:22:39 4492 3 Trace: TLS handshake: Received NEW SESSION TICKET
2021-09-16 00:22:39 4492 3 Trace: TLS handshake: Processed NEW SESSION TICKET
2021-09-16 00:22:39 4492 3 Trace: gnutls_record_recv returned spurious EAGAIN
2021-09-16 00:22:39 4492 3 Trace: tls_layer_impl::on_read()
2021-09-16 00:22:39 4492 3 Trace: CTransferSocket::OnReceive(), m_transferMode=2
2021-09-16 00:22:39 4492 3 Trace: TLS handshake: Received NEW SESSION TICKET
2021-09-16 00:22:39 4492 3 Trace: TLS handshake: Processed NEW SESSION TICKET
2021-09-16 00:22:39 4492 3 Trace: gnutls_record_recv returned spurious EAGAIN
2021-09-16 00:22:39 4492 3 Trace: tls_layer_impl::on_read()
2021-09-16 00:22:39 4492 3 Trace: CTransferSocket::OnReceive(), m_transferMode=2
2021-09-16 00:22:39 4492 3 Trace: tls_layer_impl::on_read()
2021-09-16 00:22:39 4492 3 Trace: CTransferSocket::OnReceive(), m_transferMode=2
2021-09-16 00:22:39 4492 3 Trace: tls_layer_impl::on_read()
2021-09-16 00:22:39 4492 3 Trace: CTransferSocket::OnReceive(), m_transferMode=2
2021-09-16 00:22:39 4492 3 Trace: tls_layer_impl::on_read()
2021-09-16 00:22:39 4492 3 Trace: CTransferSocket::OnReceive(), m_transferMode=2
2021-09-16 00:22:39 4492 3 Trace: tls_layer_impl::on_read()
2021-09-16 00:22:39 4492 3 Trace: CTransferSocket::OnReceive(), m_transferMode=2
2021-09-16 00:22:39 4492 3 Trace: tls_layer_impl::on_read()
2021-09-16 00:22:39 4492 3 Trace: CTransferSocket::OnReceive(), m_transferMode=2
2021-09-16 00:22:39 4492 3 Trace: tls_layer_impl::on_read()
2021-09-16 00:22:39 4492 3 Trace: CTransferSocket::OnReceive(), m_transferMode=2
2021-09-16 00:22:39 4492 3 Trace: tls_layer_impl::on_read()
2021-09-16 00:22:39 4492 3 Trace: CTransferSocket::OnReceive(), m_transferMode=2
2021-09-16 00:22:39 4492 3 Trace: CTransferSocket::OnReceive(), m_transferMode=2
2021-09-16 00:22:39 4492 3 Trace: CTransferSocket::TransferEnd(1)
2021-09-16 00:22:39 4492 3 Trace: tls_layer_impl::shutdown()
2021-09-16 00:22:39 4492 3 Trace: tls_layer_impl::continue_shutdown()
2021-09-16 00:22:39 4492 3 Trace: CFtpControlSocket::TransferEnd()
2021-09-16 00:22:39 4492 3 Trace: tls_layer_impl::on_read()
2021-09-16 00:22:39 4492 3 Trace: CFtpControlSocket::OnReceive()
2021-09-16 00:22:39 4492 3 Response: 226 Operation successful
2021-09-16 00:22:39 4492 3 Trace: CFtpRawTransferOpData::ParseResponse() in state 7
2021-09-16 00:22:39 4492 3 Trace: CFtpControlSocket::ResetOperation(0)
2021-09-16 00:22:39 4492 3 Trace: CControlSocket::ResetOperation(0)
2021-09-16 00:22:39 4492 3 Trace: CFtpRawTransferOpData::Reset(0) in state 7
2021-09-16 00:22:39 4492 3 Trace: CFtpFileTransferOpData::SubcommandResult(0) in state 7
2021-09-16 00:22:39 4492 3 Trace: CFtpControlSocket::ResetOperation(0)
2021-09-16 00:22:39 4492 3 Trace: CControlSocket::ResetOperation(0)
2021-09-16 00:22:39 4492 3 Trace: CFtpFileTransferOpData::Reset(0) in state 7
2021-09-16 00:22:39 4492 3 Status: File transfer successful, transferred 26.541 bytes in 1 second
2021-09-16 00:22:39 4492 3 Trace: CFileZillaEnginePrivate::ResetOperation(0)
2021-09-16 00:22:39 4492 3 Trace: CFileZillaEnginePrivate::ResetOperation(0)
2021-09-16 00:22:42 4492 1 Status: Disconnected from server
2021-09-16 00:22:42 4492 1 Trace: CRealControlSocket::DoClose(66)
2021-09-16 00:22:42 4492 1 Trace: CControlSocket::DoClose(66)
2021-09-16 00:22:42 4492 1 Trace: CFtpControlSocket::ResetOperation(66)
2021-09-16 00:22:42 4492 1 Trace: CControlSocket::ResetOperation(66)
2021-09-16 00:22:42 4492 1 Trace: CFileZillaEnginePrivate::ResetOperation(66)
2021-09-16 00:22:42 4492 1 Trace: CRealControlSocket::DoClose(66)
2021-09-16 00:22:42 4492 1 Trace: CControlSocket::DoClose(66)
2021-09-16 00:22:42 4492 1 Trace: CFtpControlSocket::ResetOperation(66)
2021-09-16 00:22:42 4492 1 Trace: CControlSocket::ResetOperation(66)
2021-09-16 00:22:42 4492 1 Trace: CFileZillaEnginePrivate::ResetOperation(66)
2021-09-16 00:22:42 4492 1 Trace: CControlSocket::DoClose(66)
2021-09-16 00:22:42 4492 1 Trace: CControlSocket::ResetOperation(66)
2021-09-16 00:22:42 4492 1 Trace: CFileZillaEnginePrivate::ResetOperation(66)
2021-09-16 00:22:42 4492 1 Trace: CFileZillaEnginePrivate::ResetOperation(0)
2021-09-16 00:23:09 4492 3 Status: Sending keep-alive command
2021-09-16 00:23:09 4492 3 Command: TYPE A
2021-09-16 00:23:09 4492 3 Trace: tls_layer_impl::on_read()
2021-09-16 00:23:09 4492 3 Trace: CFtpControlSocket::OnReceive()
2021-09-16 00:23:09 4492 3 Response: 200 Type set to A
2021-09-16 00:23:09 4492 3 Trace: Skipping reply after cancelled operation or keepalive command.
2021-09-16 00:23:36 4492 3 Status: Disconnected from server
2021-09-16 00:23:36 4492 3 Trace: CRealControlSocket::DoClose(66)
2021-09-16 00:23:36 4492 3 Trace: CControlSocket::DoClose(66)
2021-09-16 00:23:36 4492 3 Trace: CFtpControlSocket::ResetOperation(66)
2021-09-16 00:23:36 4492 3 Trace: CControlSocket::ResetOperation(66)
2021-09-16 00:23:36 4492 3 Trace: CFileZillaEnginePrivate::ResetOperation(66)
2021-09-16 00:23:36 4492 3 Trace: CRealControlSocket::DoClose(66)
2021-09-16 00:23:36 4492 3 Trace: CControlSocket::DoClose(66)
2021-09-16 00:23:36 4492 3 Trace: CFtpControlSocket::ResetOperation(66)
2021-09-16 00:23:36 4492 3 Trace: CControlSocket::ResetOperation(66)
2021-09-16 00:23:36 4492 3 Trace: CFileZillaEnginePrivate::ResetOperation(66)
2021-09-16 00:23:36 4492 3 Trace: CControlSocket::DoClose(66)
2021-09-16 00:23:36 4492 3 Trace: CControlSocket::ResetOperation(66)
2021-09-16 00:23:36 4492 3 Trace: CFileZillaEnginePrivate::ResetOperation(66)
2021-09-16 00:23:36 4492 3 Trace: CFileZillaEnginePrivate::ResetOperation(0)