Server 1.0.0 has some problems with small files (2xxxx Bytes)

Need help with FileZilla Server? Something does not work as expected? In this forum you may find an answer.

Moderator: Project members

Post Reply
Message
Author
User avatar
boco
Contributor
Posts: 26913
Joined: 2006-05-01 03:28
Location: Germany

Server 1.0.0 has some problems with small files (2xxxx Bytes)

#1 Post by boco » 2021-09-15 19:08

Here's an excerpt. It simply cannot retrieve these files. The fail cycle repeats until the queue entry is placed into the Failed tab. The depicted file has a size of 26,541 Bytes.

Rolled back to 1.0.0-rc5 and all is well again.

Code: Select all

21:00:33	Command:	PASV
21:00:33	Response:	227 Entering Passive Mode (10,0,0,1,200,36)
21:00:33	Command:	RETR ReadMe.html
21:00:33	Response:	150 About to start data transfer.
21:00:33	Response:	226 Operation successful
21:00:33	Error:	GnuTLS error -110 in gnutls_record_recv: The TLS connection was non-properly terminated.
21:00:33	Status:	Server did not properly shut down TLS connection
21:00:33	Error:	Could not read from transfer socket: ECONNABORTED - Connection aborted
21:00:33	Error:	File transfer failed
21:00:33	Status:	Starting download of /÷STORAGE/UUP-Converter_19100.1050_amd64_en-us_ppipro_abb92723_PPIPRO/ReadMe.html
21:00:33	Command:	PASV
21:00:33	Response:	227 Entering Passive Mode (10,0,0,1,193,184)
21:00:33	Command:	RETR ReadMe.html
21:00:33	Response:	150 About to start data transfer.
21:00:33	Response:	226 Operation successful
21:00:33	Error:	GnuTLS error -110 in gnutls_record_recv: The TLS connection was non-properly terminated.
21:00:33	Status:	Server did not properly shut down TLS connection
21:00:33	Error:	Could not read from transfer socket: ECONNABORTED - Connection aborted
21:00:33	Error:	File transfer failed
21:00:33	Status:	Starting download of /÷STORAGE/UUP-Converter_19100.1050_amd64_en-us_ppipro_abb92723_PPIPRO/ReadMe.html
21:00:33	Command:	PASV
21:00:33	Response:	227 Entering Passive Mode (10,0,0,1,200,152)
21:00:33	Command:	RETR ReadMe.html
21:00:33	Response:	150 About to start data transfer.
21:00:33	Response:	226 Operation successful
21:00:33	Error:	GnuTLS error -110 in gnutls_record_recv: The TLS connection was non-properly terminated.
21:00:33	Status:	Server did not properly shut down TLS connection
21:00:33	Error:	Could not read from transfer socket: ECONNABORTED - Connection aborted
21:00:33	Error:	File transfer failed
21:00:33	Status:	Starting download of /÷STORAGE/UUP-Converter_19100.1050_amd64_en-us_ppipro_abb92723_PPIPRO/ReadMe.html
21:00:33	Command:	PASV
21:00:33	Response:	227 Entering Passive Mode (10,0,0,1,245,111)
21:00:33	Command:	RETR ReadMe.html
21:00:33	Response:	150 About to start data transfer.
21:00:34	Response:	226 Operation successful
21:00:34	Error:	GnuTLS error -110 in gnutls_record_recv: The TLS connection was non-properly terminated.
21:00:34	Status:	Server did not properly shut down TLS connection
21:00:34	Error:	Could not read from transfer socket: ECONNABORTED - Connection aborted
21:00:34	Error:	File transfer failed
21:00:34	Status:	Starting download of /÷STORAGE/UUP-Converter_19100.1050_amd64_en-us_ppipro_abb92723_PPIPRO/ReadMe.html
21:00:34	Command:	PASV
21:00:34	Response:	227 Entering Passive Mode (10,0,0,1,245,169)
21:00:34	Command:	RETR ReadMe.html
21:00:34	Response:	150 About to start data transfer.
21:00:34	Response:	226 Operation successful
21:00:34	Error:	GnuTLS error -110 in gnutls_record_recv: The TLS connection was non-properly terminated.
21:00:34	Status:	Server did not properly shut down TLS connection
21:00:34	Error:	Could not read from transfer socket: ECONNABORTED - Connection aborted
21:00:34	Error:	File transfer failed
21:00:34	Status:	Starting download of /÷STORAGE/UUP-Converter_19100.1050_amd64_en-us_ppipro_abb92723_PPIPRO/ReadMe.html
21:00:34	Command:	PASV
21:00:34	Response:	227 Entering Passive Mode (10,0,0,1,254,159)
21:00:34	Command:	RETR ReadMe.html
21:00:34	Response:	150 About to start data transfer.
21:00:34	Response:	226 Operation successful
21:00:34	Error:	GnuTLS error -110 in gnutls_record_recv: The TLS connection was non-properly terminated.
21:00:34	Status:	Server did not properly shut down TLS connection
21:00:34	Error:	Could not read from transfer socket: ECONNABORTED - Connection aborted
21:00:34	Error:	File transfer failed
21:00:34	Status:	Starting download of /÷STORAGE/UUP-Converter_19100.1050_amd64_en-us_ppipro_abb92723_PPIPRO/ReadMe.html
21:00:34	Command:	PASV
21:00:34	Response:	227 Entering Passive Mode (10,0,0,1,236,227)
21:00:34	Command:	RETR ReadMe.html
21:00:34	Response:	150 About to start data transfer.
21:00:34	Response:	226 Operation successful
21:00:34	Error:	GnuTLS error -110 in gnutls_record_recv: The TLS connection was non-properly terminated.
21:00:34	Status:	Server did not properly shut down TLS connection
21:00:34	Error:	Could not read from transfer socket: ECONNABORTED - Connection aborted
21:00:34	Error:	File transfer failed
21:00:34	Status:	Starting download of /÷STORAGE/UUP-Converter_19100.1050_amd64_en-us_ppipro_abb92723_PPIPRO/ReadMe.html
21:00:34	Command:	PASV
21:00:34	Response:	227 Entering Passive Mode (10,0,0,1,231,119)
21:00:34	Command:	RETR ReadMe.html
21:00:34	Response:	150 About to start data transfer.
21:00:34	Response:	226 Operation successful
21:00:34	Error:	GnuTLS error -110 in gnutls_record_recv: The TLS connection was non-properly terminated.
21:00:34	Status:	Server did not properly shut down TLS connection
21:00:34	Error:	Could not read from transfer socket: ECONNABORTED - Connection aborted
21:00:34	Error:	File transfer failed
No support requests over PM! You will NOT get any reply!!!
FTP connection problems? Please read Network Configuration.
FileZilla connection test: https://filezilla-project.org/conntest.php
FileZilla Pro support: https://customerforum.fileZilla-project.org

User avatar
oibaf
Contributor
Posts: 398
Joined: 2021-07-16 21:02
First name: Fabio
Last name: Alemagna

Re: Server 1.0.0 has some problems with small files (2xxxx Bytes)

#2 Post by oibaf » 2021-09-15 20:18

Hi,

Could you please upload the relevant server's logs as well? Please, set it to maximum level (debug).

Thanks.

User avatar
botg
Site Admin
Posts: 35508
Joined: 2004-02-23 20:49
First name: Tim
Last name: Kosse

Re: Server 1.0.0 has some problems with small files (2xxxx Bytes)

#3 Post by botg » 2021-09-15 20:18

Official binaries or self-compiled FileZilla (Server)?

Any firewalls between client and server?

User avatar
boco
Contributor
Posts: 26913
Joined: 2006-05-01 03:28
Location: Germany

Re: Server 1.0.0 has some problems with small files (2xxxx Bytes)

#4 Post by boco » 2021-09-15 21:05

Will try to recreate ASAP, but I first had to get the transfer job done. Using 1.0.0-rc5 allowed me to finish the job immediately.

Edit: Official binaries. Firewalls and A/V are the same as ever (Comodo on the server, Windows default on the client), rc5 runs perfectly with them.


Normally, I would not have reported it, as the server is on (fully updated Sept. 2021) Win 7. But, as rc5 ran fine and final didn't, I decided to do it anyway.
No support requests over PM! You will NOT get any reply!!!
FTP connection problems? Please read Network Configuration.
FileZilla connection test: https://filezilla-project.org/conntest.php
FileZilla Pro support: https://customerforum.fileZilla-project.org

User avatar
boco
Contributor
Posts: 26913
Joined: 2006-05-01 03:28
Location: Germany

Re: Server 1.0.0 has some problems with small files (2xxxx Bytes)

#5 Post by boco » 2021-09-15 22:19

Server, very last attempt of the transfer. Before, the exact same cycle only repeated and repeated. Although it shows the KEX as unknown, it is the following: ECDHE-SECP384R1-RSA-PSS-RSAE-SHA384

Code: Select all

2021-09-15T21:49:46.799Z DD [FTP Session 3 10.0.0.45 sysop] tls_layer_impl::on_read()
2021-09-15T21:49:46.800Z >> [FTP Session 3 10.0.0.45 sysop] PASV
2021-09-15T21:49:46.801Z DD [FTP Session 3 10.0.0.45 sysop] TLS handshakep: About to send NEW SESSION TICKET
2021-09-15T21:49:46.802Z DD [FTP Session 3 10.0.0.45 sysop] TLS handshakep: Sent NEW SESSION TICKET
2021-09-15T21:49:46.803Z VV [FTP Session 3 10.0.0.45 sysop] Trying: data_listen_socket_->listen(1, 51516)
2021-09-15T21:49:46.831Z << [FTP Session 3 10.0.0.45 sysop] 227 Entering Passive Mode (10,0,0,1,201,60)
2021-09-15T21:49:46.837Z DD [FTP Session 3 10.0.0.45 sysop] tls_layer_impl::on_read()
2021-09-15T21:49:46.838Z >> [FTP Session 3 10.0.0.45 sysop] RETR ReadMe.html
2021-09-15T21:49:46.839Z << [FTP Session 3 10.0.0.45 sysop] 150 About to start data transfer.
2021-09-15T21:49:46.846Z VV [FTP Session 3 10.0.0.45 sysop] session::on_socket_event(): source = data listen, flag = 2, error = 0, state = -1
2021-09-15T21:49:46.847Z DD [FTP Session 3 10.0.0.45 sysop] Client wants a secure data connection.
2021-09-15T21:49:46.847Z DD [FTP Session 3 10.0.0.45 sysop] securer(1) ENTERING state = 0
2021-09-15T21:49:46.847Z DD [FTP Session 3 10.0.0.45 sysop] 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", "****")
2021-09-15T21:49:46.852Z DD [FTP Session 3 10.0.0.45 sysop] securer(1) EXITING state = 1
2021-09-15T21:49:46.853Z DD [FTP Session 3 10.0.0.45 sysop] Making the data connection secure.
2021-09-15T21:49:46.853Z DD [FTP Session 3 10.0.0.45 sysop] ~securer(1) ENTERING state = 1
2021-09-15T21:49:46.854Z VV [FTP Session 3 10.0.0.45 sysop] tls_layer_impl::server_handshake()
2021-09-15T21:49:46.855Z VV [FTP Session 3 10.0.0.45 sysop] tls_layer_impl::continue_handshake()
2021-09-15T21:49:46.856Z DD [FTP Session 3 10.0.0.45 sysop] ~securer(1) EXITING state = 2
2021-09-15T21:49:46.856Z DD [FTP Session 3 10.0.0.45 sysop] tls_layer_impl::on_send()
2021-09-15T21:49:46.857Z VV [FTP Session 3 10.0.0.45 sysop] tls_layer_impl::continue_handshake()
2021-09-15T21:49:46.858Z DD [FTP Session 3 10.0.0.45 sysop] tls_layer_impl::on_read()
2021-09-15T21:49:46.858Z VV [FTP Session 3 10.0.0.45 sysop] tls_layer_impl::continue_handshake()
2021-09-15T21:49:46.859Z DD [FTP Session 3 10.0.0.45 sysop] TLS handshakep: Received CLIENT HELLO
2021-09-15T21:49:46.860Z DD [FTP Session 3 10.0.0.45 sysop] TLS handshakep: Processed CLIENT HELLO
2021-09-15T21:49:46.861Z DD [FTP Session 3 10.0.0.45 sysop] TLS handshakep: About to send SERVER HELLO
2021-09-15T21:49:46.861Z DD [FTP Session 3 10.0.0.45 sysop] TLS handshakep: Sent SERVER HELLO
2021-09-15T21:49:46.863Z DD [FTP Session 3 10.0.0.45 sysop] TLS handshakep: About to send ENCRYPTED EXTENSIONS
2021-09-15T21:49:46.863Z DD [FTP Session 3 10.0.0.45 sysop] TLS handshakep: Sent ENCRYPTED EXTENSIONS
2021-09-15T21:49:46.864Z DD [FTP Session 3 10.0.0.45 sysop] TLS handshakep: About to send FINISHED
2021-09-15T21:49:46.864Z DD [FTP Session 3 10.0.0.45 sysop] TLS handshakep: Sent FINISHED
2021-09-15T21:49:46.868Z DD [FTP Session 3 10.0.0.45 sysop] tls_layer_impl::on_read()
2021-09-15T21:49:46.868Z VV [FTP Session 3 10.0.0.45 sysop] tls_layer_impl::continue_handshake()
2021-09-15T21:49:46.876Z DD [FTP Session 3 10.0.0.45 sysop] tls_layer_impl::on_read()
2021-09-15T21:49:46.876Z VV [FTP Session 3 10.0.0.45 sysop] tls_layer_impl::continue_handshake()
2021-09-15T21:49:46.877Z DD [FTP Session 3 10.0.0.45 sysop] TLS handshakep: Received FINISHED
2021-09-15T21:49:46.877Z DD [FTP Session 3 10.0.0.45 sysop] TLS handshakep: Processed FINISHED
2021-09-15T21:49:46.878Z II [FTP Session 3 10.0.0.45 sysop] TLS Handshake successful
2021-09-15T21:49:46.878Z II [FTP Session 3 10.0.0.45 sysop] TLS Session resumed
2021-09-15T21:49:46.878Z II [FTP Session 3 10.0.0.45 sysop] Protocol: TLS1.3, Key exchange: unknown, Cipher: AES-256-GCM, MAC: AEAD
2021-09-15T21:49:46.879Z VV [FTP Session 3 10.0.0.45 sysop] session::on_socket_event(): source = data, flag = 2, error = 0, state = 2
2021-09-15T21:49:46.880Z DD [FTP Session 3 10.0.0.45 sysop] Client wants a secure data connection.
2021-09-15T21:49:46.881Z DD [FTP Session 3 10.0.0.45 sysop] securer(1) ENTERING state = 2
2021-09-15T21:49:46.882Z DD [FTP Session 3 10.0.0.45 sysop] securer(1) EXITING state = 3
2021-09-15T21:49:46.882Z DD [FTP Session 3 10.0.0.45 sysop] The data connection is now secure.
2021-09-15T21:49:46.883Z DD [FTP Session 3 10.0.0.45 sysop] ~securer(1) ENTERING state = 3
2021-09-15T21:49:46.884Z DD [FTP Session 3 10.0.0.45 sysop] ~securer(1) EXITING state = 3
2021-09-15T21:49:46.885Z DD [FTP Session 3 10.0.0.45 sysop] CHANNEL state is being dumped:
2021-09-15T21:49:46.885Z DD [FTP Session 3 10.0.0.45 sysop] PIPE((IN)) {
    max_num_loops_           = 10
    thread_safe_             = 0
    variant_buffer_          = <2>
    buffer_                  = 
    adder_                   = 
    consumer_                = 
    waiting_for_adder_event_ = 0
    consumer_error_          = 0
    adder_error_             = 0
}
2021-09-15T21:49:46.885Z DD [FTP Session 3 10.0.0.45 sysop] PIPE((OUT)) {
    max_num_loops_           = 10
    thread_safe_             = 0
    variant_buffer_          = <2>
    buffer_                  = 
    adder_                   = 
    consumer_                = 
    waiting_for_adder_event_ = 0
    consumer_error_          = 0
    adder_error_             = 0
}
2021-09-15T21:49:46.888Z VV [FTP Session 3 10.0.0.45 sysop] tls_layer_impl::shutdown()
2021-09-15T21:49:46.889Z VV [FTP Session 3 10.0.0.45 sysop] tls_layer_impl::continue_shutdown()
2021-09-15T21:49:46.889Z VV [FTP Session 3 10.0.0.45 sysop] data_socket_->shutdown() = 11
2021-09-15T21:49:46.889Z DD [FTP Session 3 10.0.0.45 sysop/Done Event] CHANNEL state is being dumped:
2021-09-15T21:49:46.890Z DD [FTP Session 3 10.0.0.45 sysop/Done Event] PIPE((IN)) {
    max_num_loops_           = 10
    thread_safe_             = 0
    variant_buffer_          = <2>
    buffer_                  = 
    adder_                   = 
    consumer_                = 
    waiting_for_adder_event_ = 0
    consumer_error_          = 0
    adder_error_             = 0
}
2021-09-15T21:49:46.890Z DD [FTP Session 3 10.0.0.45 sysop/Done Event] PIPE((OUT)) {
    max_num_loops_           = 10
    thread_safe_             = 0
    variant_buffer_          = <2>
    buffer_                  = 
    adder_                   = 
    consumer_                = 
    waiting_for_adder_event_ = 0
    consumer_error_          = 0
    adder_error_             = 0
}
2021-09-15T21:49:46.891Z VV [FTP Session 3 10.0.0.45 sysop] session::on_socket_event(): source = data, flag = 8, error = 0, state = 3
2021-09-15T21:49:46.891Z VV [FTP Session 3 10.0.0.45 sysop] data_socket_->shutdown() = 0
2021-09-15T21:49:46.891Z << [FTP Session 3 10.0.0.45 sysop] 226 Operation successful
2021-09-15T21:49:46.892Z VV [FTP Session 3 10.0.0.45 sysop] session::close_data_connection() = 1
2021-09-15T21:49:49.314Z DD [FTP Session 1 10.0.0.45 sysop] tls_layer_impl::on_read()
2021-09-15T21:49:49.316Z >> [FTP Session 1 10.0.0.45 sysop] TYPE I
2021-09-15T21:49:49.316Z << [FTP Session 1 10.0.0.45 sysop] 200 Type set to I
2021-09-15T21:49:51.945Z DD [FTP Session 1 10.0.0.45 sysop] tls_layer_impl::on_read()
2021-09-15T21:49:51.946Z DD [FTP Session 1 10.0.0.45 sysop] tls_layer_impl::failure(-110)
2021-09-15T21:49:51.947Z !! [FTP Session 1 10.0.0.45 sysop] GnuTLS error -110 in gnutls_record_recv: The TLS connection was non-properly terminated.
2021-09-15T21:49:51.947Z == [FTP Session 1 10.0.0.45 sysop] Client did not properly shut down TLS connection
2021-09-15T21:49:51.948Z !! [FTP Session 1 10.0.0.45 sysop] Control channel closed with error from source 0. Reason: ECONNABORTED - Connection aborted.
2021-09-15T21:49:51.948Z !! [FTP Server] Session ended with error from source 0. Reason: ECONNABORTED - Connection aborted.
2021-09-15T21:49:51.948Z II [FTP Session 1 10.0.0.45] Session 0x62417e0 with ID 1 destroyed.
2021-09-15T21:50:16.930Z DD [FTP Session 3 10.0.0.45 sysop] tls_layer_impl::on_read()
2021-09-15T21:50:16.932Z >> [FTP Session 3 10.0.0.45 sysop] PWD
2021-09-15T21:50:16.933Z << [FTP Session 3 10.0.0.45 sysop] 257 "/÷STORAGE/UUP-Converter_19100.1050_amd64_en-us_ppipro_abb92723_PPIPRO" is current directory.
2021-09-15T21:50:46.956Z DD [FTP Session 3 10.0.0.45 sysop] tls_layer_impl::on_read()
2021-09-15T21:50:46.958Z DD [FTP Session 3 10.0.0.45 sysop] tls_layer_impl::failure(-110)
2021-09-15T21:50:46.959Z !! [FTP Session 3 10.0.0.45 sysop] GnuTLS error -110 in gnutls_record_recv: The TLS connection was non-properly terminated.
2021-09-15T21:50:46.959Z == [FTP Session 3 10.0.0.45 sysop] Client did not properly shut down TLS connection
2021-09-15T21:50:46.960Z >> [FTP Session 3 10.0.0.45 sysop] TYPE A
2021-09-15T21:50:46.960Z << [FTP Session 3 10.0.0.45 sysop] 200 Type set to A
2021-09-15T21:50:46.961Z !! [FTP Session 3 10.0.0.45 sysop] Control channel closed with error from source 0. Reason: ECONNABORTED - Connection aborted.
2021-09-15T21:50:46.962Z !! [FTP Server] Session ended with error from source 0. Reason: ECONNABORTED - Connection aborted.
2021-09-15T21:50:46.962Z II [FTP Session 3 10.0.0.45] Session 0x62a2590 with ID 3 destroyed.
Client:

Code: Select all

2021-09-15 23:50:51 4492 3 Trace: CFtpControlSocket::FileTransfer()
2021-09-15 23:50:51 4492 3 Trace: CControlSocket::SendNextCommand()
2021-09-15 23:50:51 4492 3 Trace: CFtpFileTransferOpData::Send() in state 0
2021-09-15 23:50:51 4492 3 Status: Starting download of /÷STORAGE/UUP-Converter_19100.1050_amd64_en-us_ppipro_abb92723_PPIPRO/ReadMe.html
2021-09-15 23:50:51 4492 3 Trace: CFtpChangeDirOpData::Send() in state 0
2021-09-15 23:50:51 4492 3 Trace: CFtpControlSocket::ResetOperation(0)
2021-09-15 23:50:51 4492 3 Trace: CControlSocket::ResetOperation(0)
2021-09-15 23:50:51 4492 3 Trace: CFtpChangeDirOpData::Reset(0) in state 0
2021-09-15 23:50:51 4492 3 Trace: CFtpFileTransferOpData::SubcommandResult(0) in state 1
2021-09-15 23:50:51 4492 3 Trace: CControlSocket::CheckOverwriteFile()
2021-09-15 23:50:51 4492 3 Trace: CControlSocket::SendNextCommand()
2021-09-15 23:50:51 4492 3 Trace: CFtpFileTransferOpData::Send() in state 5
2021-09-15 23:50:51 4492 3 Trace: CFtpRawTransferOpData::Send() in state 0
2021-09-15 23:50:51 4492 3 Trace: CFtpRawTransferOpData::Send() in state 2
2021-09-15 23:50:51 4492 3 Command: PASV
2021-09-15 23:50:51 4492 3 Trace: tls_layer_impl::on_read()
2021-09-15 23:50:51 4492 3 Trace: CFtpControlSocket::OnReceive()
2021-09-15 23:50:51 4492 3 Trace: TLS handshake: Received NEW SESSION TICKET
2021-09-15 23:50:51 4492 3 Trace: TLS handshake: Processed NEW SESSION TICKET
2021-09-15 23:50:51 4492 3 Trace: gnutls_record_recv returned spurious EAGAIN
2021-09-15 23:50:51 4492 3 Trace: tls_layer_impl::on_read()
2021-09-15 23:50:51 4492 3 Trace: CFtpControlSocket::OnReceive()
2021-09-15 23:50:51 4492 3 Response: 227 Entering Passive Mode (10,0,0,1,201,60)
2021-09-15 23:50:51 4492 3 Trace: CFtpRawTransferOpData::ParseResponse() in state 2
2021-09-15 23:50:51 4492 3 Trace: CControlSocket::SendNextCommand()
2021-09-15 23:50:51 4492 3 Trace: CFtpRawTransferOpData::Send() in state 4
2021-09-15 23:50:51 4492 3 Trace: Binding data connection source IP to control connection source IP 10.0.0.45
2021-09-15 23:50:51 4492 3 Trace: tls_layer_impl::client_handshake()
2021-09-15 23:50:51 4492 3 Trace: Trying to resume existing TLS session.
2021-09-15 23:50:51 4492 3 Command: RETR ReadMe.html
2021-09-15 23:50:51 4492 3 Trace: tls_layer_impl::on_send()
2021-09-15 23:50:51 4492 3 Trace: tls_layer_impl::continue_handshake()
2021-09-15 23:50:51 4492 3 Trace: TLS handshake: About to send CLIENT HELLO
2021-09-15 23:50:51 4492 3 Trace: TLS handshake: Sent CLIENT HELLO
2021-09-15 23:50:51 4492 3 Trace: tls_layer_impl::on_read()
2021-09-15 23:50:51 4492 3 Trace: CFtpControlSocket::OnReceive()
2021-09-15 23:50:51 4492 3 Response: 150 About to start data transfer.
2021-09-15 23:50:51 4492 3 Trace: CFtpRawTransferOpData::ParseResponse() in state 4
2021-09-15 23:50:51 4492 3 Trace: CControlSocket::SendNextCommand()
2021-09-15 23:50:51 4492 3 Trace: CFtpRawTransferOpData::Send() in state 5
2021-09-15 23:50:51 4492 3 Trace: tls_layer_impl::on_read()
2021-09-15 23:50:51 4492 3 Trace: tls_layer_impl::continue_handshake()
2021-09-15 23:50:51 4492 3 Trace: TLS handshake: Received SERVER HELLO
2021-09-15 23:50:51 4492 3 Trace: TLS handshake: Processed SERVER HELLO
2021-09-15 23:50:51 4492 3 Trace: tls_layer_impl::on_read()
2021-09-15 23:50:51 4492 3 Trace: tls_layer_impl::continue_handshake()
2021-09-15 23:50:51 4492 3 Trace: TLS handshake: Received ENCRYPTED EXTENSIONS
2021-09-15 23:50:51 4492 3 Trace: TLS handshake: Processed ENCRYPTED EXTENSIONS
2021-09-15 23:50:51 4492 3 Trace: tls_layer_impl::on_read()
2021-09-15 23:50:51 4492 3 Trace: tls_layer_impl::continue_handshake()
2021-09-15 23:50:51 4492 3 Trace: TLS handshake: Received FINISHED
2021-09-15 23:50:51 4492 3 Trace: TLS handshake: Processed FINISHED
2021-09-15 23:50:51 4492 3 Trace: TLS handshake: About to send FINISHED
2021-09-15 23:50:51 4492 3 Trace: TLS handshake: Sent FINISHED
2021-09-15 23:50:51 4492 3 Trace: TLS Handshake successful
2021-09-15 23:50:51 4492 3 Trace: TLS Session resumed
2021-09-15 23:50:51 4492 3 Trace: Protocol: TLS1.3, Key exchange: unknown, Cipher: AES-256-GCM, MAC: AEAD
2021-09-15 23:50:51 4492 3 Trace: tls_layer_impl::verify_certificate()
2021-09-15 23:50:51 4492 3 Trace: CTransferSocket::OnConnect
2021-09-15 23:50:51 4492 3 Trace: CTransferSocket::OnReceive(), m_transferMode=2
2021-09-15 23:50:51 4492 3 Trace: tls_layer_impl::on_read()
2021-09-15 23:50:51 4492 3 Trace: CTransferSocket::OnReceive(), m_transferMode=2
2021-09-15 23:50:51 4492 3 Trace: tls_layer_impl::on_read()
2021-09-15 23:50:51 4492 3 Trace: tls_layer_impl::on_read()
2021-09-15 23:50:51 4492 3 Trace: CFtpControlSocket::OnReceive()
2021-09-15 23:50:51 4492 3 Response: 226 Operation successful
2021-09-15 23:50:51 4492 3 Trace: CFtpRawTransferOpData::ParseResponse() in state 5
2021-09-15 23:50:51 4492 3 Trace: CControlSocket::SendNextCommand()
2021-09-15 23:50:51 4492 3 Trace: CFtpRawTransferOpData::Send() in state 8
2021-09-15 23:50:51 4492 3 Trace: CTransferSocket::OnReceive(), m_transferMode=2
2021-09-15 23:50:51 4492 3 Trace: tls_layer_impl::on_read()
2021-09-15 23:50:51 4492 3 Trace: CTransferSocket::OnReceive(), m_transferMode=2
2021-09-15 23:50:51 4492 3 Trace: tls_layer_impl::on_read()
2021-09-15 23:50:51 4492 3 Trace: CTransferSocket::OnReceive(), m_transferMode=2
2021-09-15 23:50:51 4492 3 Trace: tls_layer_impl::on_read()
2021-09-15 23:50:51 4492 3 Trace: CTransferSocket::OnReceive(), m_transferMode=2
2021-09-15 23:50:51 4492 3 Trace: tls_layer_impl::on_read()
2021-09-15 23:50:51 4492 3 Trace: CTransferSocket::OnReceive(), m_transferMode=2
2021-09-15 23:50:51 4492 3 Trace: tls_layer_impl::on_read()
2021-09-15 23:50:51 4492 3 Trace: CTransferSocket::OnReceive(), m_transferMode=2
2021-09-15 23:50:51 4492 3 Trace: tls_layer_impl::failure(-110)
2021-09-15 23:50:51 4492 3 Error: GnuTLS error -110 in gnutls_record_recv: The TLS connection was non-properly terminated.
2021-09-15 23:50:51 4492 3 Status: Server did not properly shut down TLS connection
2021-09-15 23:50:51 4492 3 Error: Could not read from transfer socket: ECONNABORTED - Connection aborted
2021-09-15 23:50:51 4492 3 Trace: CTransferSocket::TransferEnd(3)
2021-09-15 23:50:51 4492 3 Trace: CFtpControlSocket::TransferEnd()
2021-09-15 23:50:51 4492 3 Trace: CFtpControlSocket::ResetOperation(2)
2021-09-15 23:50:51 4492 3 Trace: Deleting empty file 'D:\ReadMe.html'
2021-09-15 23:50:51 4492 3 Trace: CControlSocket::ResetOperation(2)
2021-09-15 23:50:51 4492 3 Trace: CFtpRawTransferOpData::Reset(2) in state 8
2021-09-15 23:50:51 4492 3 Trace: CFtpFileTransferOpData::SubcommandResult(2) in state 7
2021-09-15 23:50:51 4492 3 Trace: CFtpControlSocket::ResetOperation(2)
2021-09-15 23:50:51 4492 3 Trace: CControlSocket::ResetOperation(2)
2021-09-15 23:50:51 4492 3 Trace: CFtpFileTransferOpData::Reset(2) in state 7
2021-09-15 23:50:51 4492 3 Error: File transfer failed
2021-09-15 23:50:51 4492 3 Trace: CFileZillaEnginePrivate::ResetOperation(2)
2021-09-15 23:50:53 4492 1 Status: Sending keep-alive command
2021-09-15 23:50:53 4492 1 Command: TYPE I
2021-09-15 23:50:53 4492 1 Trace: tls_layer_impl::on_read()
2021-09-15 23:50:53 4492 1 Trace: CFtpControlSocket::OnReceive()
2021-09-15 23:50:53 4492 1 Response: 200 Type set to I
2021-09-15 23:50:53 4492 1 Trace: Skipping reply after cancelled operation or keepalive command.
2021-09-15 23:50:56 4492 1 Status: Disconnected from server
2021-09-15 23:50:56 4492 1 Trace: CRealControlSocket::DoClose(66)
2021-09-15 23:50:56 4492 1 Trace: CControlSocket::DoClose(66)
2021-09-15 23:50:56 4492 1 Trace: CFtpControlSocket::ResetOperation(66)
2021-09-15 23:50:56 4492 1 Trace: CControlSocket::ResetOperation(66)
2021-09-15 23:50:56 4492 1 Trace: CFileZillaEnginePrivate::ResetOperation(66)
2021-09-15 23:50:56 4492 1 Trace: CRealControlSocket::DoClose(66)
2021-09-15 23:50:56 4492 1 Trace: CControlSocket::DoClose(66)
2021-09-15 23:50:56 4492 1 Trace: CFtpControlSocket::ResetOperation(66)
2021-09-15 23:50:56 4492 1 Trace: CControlSocket::ResetOperation(66)
2021-09-15 23:50:56 4492 1 Trace: CFileZillaEnginePrivate::ResetOperation(66)
2021-09-15 23:50:56 4492 1 Trace: CControlSocket::DoClose(66)
2021-09-15 23:50:56 4492 1 Trace: CControlSocket::ResetOperation(66)
2021-09-15 23:50:56 4492 1 Trace: CFileZillaEnginePrivate::ResetOperation(66)
2021-09-15 23:50:56 4492 1 Trace: CFileZillaEnginePrivate::ResetOperation(0)
2021-09-15 23:51:21 4492 3 Status: Sending keep-alive command
2021-09-15 23:51:21 4492 3 Command: PWD
2021-09-15 23:51:21 4492 3 Trace: tls_layer_impl::on_read()
2021-09-15 23:51:21 4492 3 Trace: CFtpControlSocket::OnReceive()
2021-09-15 23:51:21 4492 3 Response: 257 "/÷STORAGE/UUP-Converter_19100.1050_amd64_en-us_ppipro_abb92723_PPIPRO" is current directory.
2021-09-15 23:51:21 4492 3 Trace: Skipping reply after cancelled operation or keepalive command.
2021-09-15 23:51:51 4492 3 Status: Sending keep-alive command
2021-09-15 23:51:51 4492 3 Command: TYPE A
2021-09-15 23:51:51 4492 3 Status: Disconnected from server
2021-09-15 23:51:51 4492 3 Trace: CRealControlSocket::DoClose(66)
2021-09-15 23:51:51 4492 3 Trace: CControlSocket::DoClose(66)
2021-09-15 23:51:51 4492 3 Trace: CFtpControlSocket::ResetOperation(66)
2021-09-15 23:51:51 4492 3 Trace: CControlSocket::ResetOperation(66)
2021-09-15 23:51:51 4492 3 Trace: CFileZillaEnginePrivate::ResetOperation(66)
2021-09-15 23:51:51 4492 3 Trace: CRealControlSocket::DoClose(66)
2021-09-15 23:51:51 4492 3 Trace: CControlSocket::DoClose(66)
2021-09-15 23:51:51 4492 3 Trace: CFtpControlSocket::ResetOperation(66)
2021-09-15 23:51:51 4492 3 Trace: CControlSocket::ResetOperation(66)
2021-09-15 23:51:51 4492 3 Trace: CFileZillaEnginePrivate::ResetOperation(66)
2021-09-15 23:51:51 4492 3 Trace: CControlSocket::DoClose(66)
2021-09-15 23:51:51 4492 3 Trace: CControlSocket::ResetOperation(66)
2021-09-15 23:51:51 4492 3 Trace: CFileZillaEnginePrivate::ResetOperation(66)
2021-09-15 23:51:51 4492 3 Trace: CFileZillaEnginePrivate::ResetOperation(0)
No support requests over PM! You will NOT get any reply!!!
FTP connection problems? Please read Network Configuration.
FileZilla connection test: https://filezilla-project.org/conntest.php
FileZilla Pro support: https://customerforum.fileZilla-project.org

User avatar
botg
Site Admin
Posts: 35508
Joined: 2004-02-23 20:49
First name: Tim
Last name: Kosse

Re: Server 1.0.0 has some problems with small files (2xxxx Bytes)

#6 Post by botg » 2021-09-15 22:29

Unknown kex is correct, being a resumed session, there is no kex.


Could you please synchronize your clocks? Either the logs are from different sessions, or your clock is more inaccurate than a popular opinion.

User avatar
boco
Contributor
Posts: 26913
Joined: 2006-05-01 03:28
Location: Germany

Re: Server 1.0.0 has some problems with small files (2xxxx Bytes)

#7 Post by boco » 2021-09-15 22:31

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)
No support requests over PM! You will NOT get any reply!!!
FTP connection problems? Please read Network Configuration.
FileZilla connection test: https://filezilla-project.org/conntest.php
FileZilla Pro support: https://customerforum.fileZilla-project.org

User avatar
boco
Contributor
Posts: 26913
Joined: 2006-05-01 03:28
Location: Germany

Re: Server 1.0.0 has some problems with small files (2xxxx Bytes)

#8 Post by boco » 2021-09-15 22:33

botg wrote:
2021-09-15 22:29
Unknown kex is correct, being a resumed session, there is no kex.


Could you please synchronize your clocks? Either the logs are from different sessions, or your clock is more inaccurate than a popular opinion.
About the clocks, yes, I've set up time sync after noticing it, now they are the same. I carefully matched the two logs, though.
No support requests over PM! You will NOT get any reply!!!
FTP connection problems? Please read Network Configuration.
FileZilla connection test: https://filezilla-project.org/conntest.php
FileZilla Pro support: https://customerforum.fileZilla-project.org

User avatar
oibaf
Contributor
Posts: 398
Joined: 2021-07-16 21:02
First name: Fabio
Last name: Alemagna

Re: Server 1.0.0 has some problems with small files (2xxxx Bytes)

#9 Post by oibaf » 2021-09-15 23:48

Thank you for the report, boco, I believe I found the issue.

If you've already got an environment set up to compile the FileZilla Server, would you be willing to test a one line patch?

User avatar
boco
Contributor
Posts: 26913
Joined: 2006-05-01 03:28
Location: Germany

Re: Server 1.0.0 has some problems with small files (2xxxx Bytes)

#10 Post by boco » 2021-09-16 00:29

No, unfortunately not, sorry. Is there any guide for setting up such an environment for the new server? There are also no nightlies for testing, right?
No support requests over PM! You will NOT get any reply!!!
FTP connection problems? Please read Network Configuration.
FileZilla connection test: https://filezilla-project.org/conntest.php
FileZilla Pro support: https://customerforum.fileZilla-project.org

User avatar
botg
Site Admin
Posts: 35508
Joined: 2004-02-23 20:49
First name: Tim
Last name: Kosse

Re: Server 1.0.0 has some problems with small files (2xxxx Bytes)

#11 Post by botg » 2021-09-16 07:58

https://filezilla-project.org/nightly.php?type=server Your kilometerage may vary.

The build environment is the same for both client and server. Follow the client guide in the Wiki and as a last step, instead of building the client, build the server.

User avatar
boco
Contributor
Posts: 26913
Joined: 2006-05-01 03:28
Location: Germany

Re: Server 1.0.0 has some problems with small files (2xxxx Bytes)

#12 Post by boco » 2021-09-18 00:45

Hi Tim and Fabio,

using the Nightly from 2021-09-16 or higher, the transfer errors seem to be gone. It's chugging along nicely. 8)
No support requests over PM! You will NOT get any reply!!!
FTP connection problems? Please read Network Configuration.
FileZilla connection test: https://filezilla-project.org/conntest.php
FileZilla Pro support: https://customerforum.fileZilla-project.org

Post Reply