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: 26899
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
### BEGIN SIGNATURE BLOCK ###
No support requests per PM! You will NOT get any reply!!!
FTP connection problems? Please do yourself a favor and read Network Configuration.
FileZilla connection test: https://filezilla-project.org/conntest.php
### END SIGNATURE BLOCK ###

User avatar
oibaf
Contributor
Posts: 396
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: 35492
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: 26899
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.
### BEGIN SIGNATURE BLOCK ###
No support requests per PM! You will NOT get any reply!!!
FTP connection problems? Please do yourself a favor and read Network Configuration.
FileZilla connection test: https://filezilla-project.org/conntest.php
### END SIGNATURE BLOCK ###

User avatar
boco
Contributor
Posts: 26899
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)
### BEGIN SIGNATURE BLOCK ###
No support requests per PM! You will NOT get any reply!!!
FTP connection problems? Please do yourself a favor and read Network Configuration.
FileZilla connection test: https://filezilla-project.org/conntest.php
### END SIGNATURE BLOCK ###

User avatar
botg
Site Admin
Posts: 35492
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: 26899
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)
### BEGIN SIGNATURE BLOCK ###
No support requests per PM! You will NOT get any reply!!!
FTP connection problems? Please do yourself a favor and read Network Configuration.
FileZilla connection test: https://filezilla-project.org/conntest.php
### END SIGNATURE BLOCK ###

User avatar
boco
Contributor
Posts: 26899
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.
### BEGIN SIGNATURE BLOCK ###
No support requests per PM! You will NOT get any reply!!!
FTP connection problems? Please do yourself a favor and read Network Configuration.
FileZilla connection test: https://filezilla-project.org/conntest.php
### END SIGNATURE BLOCK ###

User avatar
oibaf
Contributor
Posts: 396
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: 26899
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?
### BEGIN SIGNATURE BLOCK ###
No support requests per PM! You will NOT get any reply!!!
FTP connection problems? Please do yourself a favor and read Network Configuration.
FileZilla connection test: https://filezilla-project.org/conntest.php
### END SIGNATURE BLOCK ###

User avatar
botg
Site Admin
Posts: 35492
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: 26899
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)
### BEGIN SIGNATURE BLOCK ###
No support requests per PM! You will NOT get any reply!!!
FTP connection problems? Please do yourself a favor and read Network Configuration.
FileZilla connection test: https://filezilla-project.org/conntest.php
### END SIGNATURE BLOCK ###

Post Reply