Opened 8 years ago

Closed 7 years ago

Last modified 6 years ago

#7287 closed Bug report (fixed)

Uploading problems with encryption (Linux only)

Reported by: PressimistPrime Owned by:
Priority: high Component: FileZilla Client
Keywords: Cc: Nico.Laus.2001@…, jiri.horky@…
Component version: Operating system type: Linux
Operating system version: Arch Linux

Description

This log is anonymized. Size of cloudy_violet.JPG is 833,949 bytes. Filezilla 3.4.0 client (Linux) with encryption (Require explicit FTP over TLS).The connection timeout is nonsense. The FTP server is the last one which is sending an ACK and is waiting for Filezilla to do something - checked with wireshark. Without encryption, everything is working fine under Linux - but with encryption see this log. Only max. 180,224 bytes per session possible. Firewall was not active. Filezilla 3.4.0 client under Windows Vista is working flawlessly (with no encryption and encryption, too).

Status:	Resolving address of my.homepage.webpack.hosteurope.de
Status:	Connecting to 123.123.123.123:21...
Status:	Connection established, waiting for welcome message...
Response:	220 ::ffff:123.123.123.123 FTP server ready
Command:	AUTH TLS
Response:	234 AUTH TLS successful
Status:	Initializing TLS...
Status:	Verifying certificate...
Command:	USER account-xyz
Status:	TLS/SSL connection established.
Response:	331 Password required for account-xyz
Command:	PASS *****************
Response:	230 User account-xyz logged in
Command:	SYST
Response:	215 UNIX Type: L8
Command:	FEAT
Response:	550 FEAT: Operation not permitted
Command:	PBSZ 0
Response:	200 PBSZ 0 successful
Command:	PROT P
Response:	200 Protection set to Private
Status:	Connected
Status:	Retrieving directory listing...
Command:	PWD
Response:	257 "/" is the current directory
Command:	TYPE I
Response:	200 Type set to I
Command:	PASV
Response:	227 Entering Passive Mode (123,123,123,123,203,69).
Command:	LIST
Response:	150 Opening ASCII mode data connection for file list
Response:	226 Transfer complete
Status:	Directory listing successful
Status:	Retrieving directory listing...
Command:	CWD www
Response:	250 CWD command successful
Command:	PWD
Response:	257 "/www" is the current directory
Command:	PASV
Response:	227 Entering Passive Mode (123,123,123,123,203,156).
Command:	LIST
Response:	150 Opening ASCII mode data connection for file list
Response:	226 Transfer complete
Status:	Directory listing successful
Status:	Resolving address of my.homepage.webpack.hosteurope.de
Status:	Connecting to 123.123.123.123:21...
Status:	Connection established, waiting for welcome message...
Response:	220 ::ffff:123.123.123.123 FTP server ready
Command:	AUTH TLS
Response:	234 AUTH TLS successful
Status:	Initializing TLS...
Status:	Verifying certificate...
Command:	USER account-xyz
Status:	TLS/SSL connection established.
Response:	331 Password required for account-xyz
Command:	PASS *****************
Response:	230 User account-xyz logged in
Command:	PBSZ 0
Response:	200 PBSZ 0 successful
Command:	PROT P
Response:	200 Protection set to Private
Status:	Connected
Status:	Starting upload of /home/itsme/Desktop/cloudy_violet.JPG
Command:	CWD /www
Response:	250 CWD command successful
Command:	PWD
Response:	257 "/www" is the current directory
Command:	TYPE I
Response:	200 Type set to I
Command:	PASV
Response:	227 Entering Passive Mode (123,123,123,123,202,66).
Command:	STOR cloudy_violet.JPG
Response:	150 Opening BINARY mode data connection for cloudy_violet.JPG
Error:	Connection timed out
Error:	File transfer failed after transferring 180,224 bytes in 21 seconds
Status:	Resolving address of my.homepage.webpack.hosteurope.de
Status:	Connecting to 123.123.123.123:21...
Status:	Connection established, waiting for welcome message...
Response:	220 ::ffff:123.123.123.123 FTP server ready
Command:	AUTH TLS
Response:	234 AUTH TLS successful
Status:	Initializing TLS...
Status:	Verifying certificate...
Command:	USER account-xyz
Status:	TLS/SSL connection established.
Response:	331 Password required for account-xyz
Command:	PASS *****************
Response:	230 User account-xyz logged in
Command:	PBSZ 0
Response:	200 PBSZ 0 successful
Command:	PROT P
Response:	200 Protection set to Private
Status:	Connected
Status:	Starting upload of /home/itsme/Desktop/cloudy_violet.JPG
Command:	CWD /www
Response:	250 CWD command successful
Status:	Retrieving directory listing...
Command:	TYPE I
Response:	200 Type set to I
Command:	PASV
Response:	227 Entering Passive Mode (123,123,123,123,200,14).
Command:	LIST
Response:	150 Opening ASCII mode data connection for file list
Response:	226 Transfer complete
Command:	PASV
Response:	227 Entering Passive Mode (123,123,123,123,203,55).
Command:	APPE cloudy_violet.JPG
Response:	150 Opening BINARY mode data connection for cloudy_violet.JPG
Error:	Connection timed out
Error:	File transfer failed after transferring 180,224 bytes in 21 seconds
Status:	Resolving address of my.homepage.webpack.hosteurope.de
Status:	Connecting to 123.123.123.123:21...
Status:	Connection established, waiting for welcome message...
Response:	220 ::ffff:123.123.123.123 FTP server ready
Command:	AUTH TLS
Response:	234 AUTH TLS successful
Status:	Initializing TLS...
Status:	Verifying certificate...
Command:	USER account-xyz
Status:	TLS/SSL connection established.
Response:	331 Password required for account-xyz
Command:	PASS *****************
Response:	230 User account-xyz logged in
Command:	PBSZ 0
Response:	200 PBSZ 0 successful
Command:	PROT P
Response:	200 Protection set to Private
Status:	Connected
Status:	Starting upload of /home/itsme/Desktop/cloudy_violet.JPG
Command:	CWD /www
Response:	250 CWD command successful
Status:	Retrieving directory listing...
Command:	TYPE I
Response:	200 Type set to I
Command:	PASV
Response:	227 Entering Passive Mode (123,123,123,123,209,89).
Command:	LIST
Response:	150 Opening ASCII mode data connection for file list
Response:	226 Transfer complete
Command:	PASV
Response:	227 Entering Passive Mode (123,123,123,123,197,213).
Command:	APPE cloudy_violet.JPG
Response:	150 Opening BINARY mode data connection for cloudy_violet.JPG
Error:	Connection timed out
Error:	File transfer failed after transferring 180,224 bytes in 21 seconds
Status:	Resolving address of my.homepage.webpack.hosteurope.de
Status:	Connecting to 123.123.123.123:21...
Status:	Connection established, waiting for welcome message...
Response:	220 ::ffff:123.123.123.123 FTP server ready
Command:	AUTH TLS
Response:	234 AUTH TLS successful
Status:	Initializing TLS...
Status:	Verifying certificate...
Command:	USER account-xyz
Status:	TLS/SSL connection established.
Response:	331 Password required for account-xyz
Command:	PASS *****************
Response:	230 User account-xyz logged in
Command:	PBSZ 0
Response:	200 PBSZ 0 successful
Command:	PROT P
Response:	200 Protection set to Private
Status:	Connected
Status:	Starting upload of /home/itsme/Desktop/cloudy_violet.JPG
Command:	CWD /www
Response:	250 CWD command successful
Status:	Retrieving directory listing...
Command:	TYPE I
Response:	200 Type set to I
Command:	PASV
Response:	227 Entering Passive Mode (123,123,123,123,210,188).
Command:	LIST
Response:	150 Opening ASCII mode data connection for file list
Response:	226 Transfer complete
Command:	PASV
Response:	227 Entering Passive Mode (123,123,123,123,208,35).
Command:	APPE cloudy_violet.JPG
Response:	150 Opening BINARY mode data connection for cloudy_violet.JPG
Error:	Connection timed out
Error:	File transfer failed after transferring 180,224 bytes in 21 seconds
Status:	Resolving address of my.homepage.webpack.hosteurope.de
Status:	Connecting to 123.123.123.123:21...
Status:	Connection established, waiting for welcome message...
Response:	220 ::ffff:123.123.123.123 FTP server ready
Command:	AUTH TLS
Response:	234 AUTH TLS successful
Status:	Initializing TLS...
Status:	Verifying certificate...
Command:	USER account-xyz
Status:	TLS/SSL connection established.
Response:	331 Password required for account-xyz
Command:	PASS *****************
Response:	230 User account-xyz logged in
Command:	PBSZ 0
Response:	200 PBSZ 0 successful
Command:	PROT P
Response:	200 Protection set to Private
Status:	Connected
Status:	Starting upload of /home/itsme/Desktop/cloudy_violet.JPG
Command:	CWD /www
Response:	250 CWD command successful
Status:	Retrieving directory listing...
Command:	TYPE I
Response:	200 Type set to I
Command:	PASV
Response:	227 Entering Passive Mode (123,123,123,123,205,231).
Command:	LIST
Response:	150 Opening ASCII mode data connection for file list
Response:	226 Transfer complete
Command:	PASV
Response:	227 Entering Passive Mode (123,123,123,123,210,238).
Command:	APPE cloudy_violet.JPG
Response:	150 Opening BINARY mode data connection for cloudy_violet.JPG
Response:	226 Transfer complete
Status:	File transfer successful, transferred 113,053 bytes in 1 second
Status:	Retrieving directory listing...
Command:	PASV
Response:	227 Entering Passive Mode (123,123,123,123,198,187).
Command:	LIST
Response:	150 Opening ASCII mode data connection for file list
Response:	226 Transfer complete
Status:	Directory listing successful

Change History (8)

comment:1 Changed 8 years ago by Gökhan Özbulak

With v3.5.0, we also hit same issue on Pardus GNU/Linux. I also tested with v3.5.1 rc but the issue still exists. Do you have any patch/plan for this issue?

comment:2 Changed 7 years ago by Nico

Cc: Nico.Laus.2001@… added

this bug still seems present (using openSUSE 12.1, x86_64, gnutls 3.0.19, filezilla 3.5.3)

comment:3 Changed 7 years ago by Jiri Horky

Cc: jiri.horky@… added

Hi,

exactly the same problem here, using v3.5.3 64bit on Gentoo, gnutls 2.12.18, against vsftpd server v2.3.2-3.3.1

Regareds
Jiri Horky

comment:4 Changed 7 years ago by Jiri Horky

Ok, so I have tried to debug it little bit further, all based on latest source code tarball (3.5.3). I think there are several problems. First, lets have a look at what debug logs says:

01:31:30	Status:	Resolving address of xxxxxxxxxxxxxxxxxxxx
01:31:30	Status:	Connecting to xxxxxxxxxxxx:21...
01:31:30	Status:	Connection established, waiting for welcome message...
01:31:30	Trace:	CFtpControlSocket::OnReceive()
01:31:30	Response:	220 (vsFTPd 2.3.2)
01:31:30	Trace:	CFtpControlSocket::SendNextCommand()
01:31:30	Command:	AUTH TLS
01:31:30	Trace:	CFtpControlSocket::OnReceive()
01:31:30	Response:	234 Proceed with negotiation.
01:31:30	Status:	Initializing TLS...
01:31:30	Trace:	CTlsSocket::Handshake()
01:31:30	Trace:	CTlsSocket::ContinueHandshake()
01:31:30	Trace:	CTlsSocket::OnSend()
01:31:30	Trace:	CTlsSocket::OnRead()
01:31:30	Trace:	CTlsSocket::ContinueHandshake()
01:31:30	Trace:	CTlsSocket::OnRead()
01:31:30	Trace:	CTlsSocket::ContinueHandshake()
01:31:30	Trace:	CTlsSocket::OnRead()
01:31:30	Trace:	CTlsSocket::ContinueHandshake()
01:31:30	Trace:	CTlsSocket::OnRead()
01:31:30	Trace:	CTlsSocket::ContinueHandshake()
01:31:30	Trace:	TLS Handshake successful
01:31:30	Trace:	Cipher: AES-128-CBC, MAC: SHA1
01:31:30	Status:	Verifying certificate...
01:31:30	Trace:	CFtpControlSocket::SendNextCommand()
01:31:30	Command:	USER xxxxxxxxx
01:31:30	Status:	TLS/SSL connection established.
01:31:30	Trace:	CTlsSocket::OnRead()
01:31:30	Trace:	CFtpControlSocket::OnReceive()
01:31:30	Response:	331 Please specify the password.
01:31:30	Trace:	CFtpControlSocket::SendNextCommand()
01:31:30	Command:	PASS *********
01:31:30	Trace:	CTlsSocket::OnRead()
01:31:30	Trace:	CFtpControlSocket::OnReceive()
01:31:30	Response:	230 Login successful.
01:31:30	Trace:	CFtpControlSocket::SendNextCommand()
01:31:30	Command:	SYST
01:31:30	Trace:	CTlsSocket::OnRead()
01:31:30	Trace:	CFtpControlSocket::OnReceive()
01:31:30	Response:	215 UNIX Type: L8
01:31:30	Trace:	CFtpControlSocket::SendNextCommand()
01:31:30	Command:	FEAT
01:31:30	Trace:	CTlsSocket::OnRead()
01:31:30	Trace:	CFtpControlSocket::OnReceive()
01:31:30	Response:	211-Features:
01:31:30	Response:	 AUTH SSL
01:31:30	Response:	 AUTH TLS
01:31:30	Response:	 EPRT
01:31:30	Response:	 EPSV
01:31:30	Trace:	CTlsSocket::OnRead()
01:31:30	Trace:	CFtpControlSocket::OnReceive()
01:31:30	Response:	 MDTM
01:31:30	Response:	 PASV
01:31:30	Response:	 PBSZ
01:31:30	Response:	 PROT
01:31:30	Response:	 REST STREAM
01:31:30	Response:	 SIZE
01:31:30	Response:	 TVFS
01:31:30	Response:	 UTF8
01:31:30	Response:	211 End
01:31:30	Trace:	CFtpControlSocket::SendNextCommand()
01:31:30	Command:	OPTS UTF8 ON
01:31:30	Trace:	CTlsSocket::OnRead()
01:31:30	Trace:	CFtpControlSocket::OnReceive()
01:31:30	Response:	200 Always in UTF8 mode.
01:31:30	Trace:	CFtpControlSocket::SendNextCommand()
01:31:30	Command:	PBSZ 0
01:31:30	Trace:	CTlsSocket::OnRead()
01:31:30	Trace:	CFtpControlSocket::OnReceive()
01:31:30	Response:	200 PBSZ set to 0.
01:31:30	Trace:	CFtpControlSocket::SendNextCommand()
01:31:30	Command:	PROT P
01:31:30	Trace:	CTlsSocket::OnRead()
01:31:30	Trace:	CFtpControlSocket::OnReceive()
01:31:30	Response:	200 PROT now Private.
01:31:30	Status:	Connected
01:31:30	Trace:	CFtpControlSocket::ResetOperation(0)
01:31:30	Trace:	CControlSocket::ResetOperation(0)
01:31:30	Trace:	CFileZillaEnginePrivate::ResetOperation(0)
01:31:30	Status:	Retrieving directory listing...
01:31:30	Trace:	CFtpControlSocket::SendNextCommand()
01:31:30	Trace:	CFtpControlSocket::ChangeDirSend()
01:31:30	Command:	CWD /
01:31:30	Trace:	CTlsSocket::OnRead()
01:31:30	Trace:	CFtpControlSocket::OnReceive()
01:31:30	Response:	250 Directory successfully changed.
01:31:30	Trace:	CFtpControlSocket::SendNextCommand()
01:31:30	Trace:	CFtpControlSocket::ChangeDirSend()
01:31:30	Command:	PWD
01:31:30	Trace:	CTlsSocket::OnRead()
01:31:30	Trace:	CFtpControlSocket::OnReceive()
01:31:30	Response:	257 "/"
01:31:30	Trace:	CFtpControlSocket::ResetOperation(0)
01:31:30	Trace:	CControlSocket::ResetOperation(0)
01:31:30	Trace:	CFtpControlSocket::ParseSubcommandResult(0)
01:31:30	Trace:	CFtpControlSocket::ListSubcommandResult()
01:31:30	Trace:	  state = 1
01:31:30	Trace:	CFtpControlSocket::SendNextCommand()
01:31:30	Trace:	CFtpControlSocket::TransferSend()
01:31:30	Trace:	  state = 1
01:31:30	Command:	TYPE I
01:31:31	Trace:	CTlsSocket::OnRead()
01:31:31	Trace:	CFtpControlSocket::OnReceive()
01:31:31	Response:	200 Switching to Binary mode.
01:31:31	Trace:	CFtpControlSocket::TransferParseResponse()
01:31:31	Trace:	  code = 2
01:31:31	Trace:	  state = 1
01:31:31	Trace:	CFtpControlSocket::SendNextCommand()
01:31:31	Trace:	CFtpControlSocket::TransferSend()
01:31:31	Trace:	  state = 2
01:31:31	Command:	PASV
01:31:31	Trace:	CTlsSocket::OnRead()
01:31:31	Trace:	CFtpControlSocket::OnReceive()
01:31:31	Response:	227 Entering Passive Mode (xxxxxxxxxxxx,167,7).
01:31:31	Trace:	CFtpControlSocket::TransferParseResponse()
01:31:31	Trace:	  code = 2
01:31:31	Trace:	  state = 2
01:31:31	Trace:	CFtpControlSocket::SendNextCommand()
01:31:31	Trace:	CFtpControlSocket::TransferSend()
01:31:31	Trace:	  state = 4
01:31:31	Command:	LIST
01:31:31	Trace:	CTransferSocket::OnConnect
01:31:31	Trace:	CTlsSocket::Handshake()
01:31:31	Trace:	gnutls_session_get_data on primary socket failed: -51
01:31:31	Trace:	CTlsSocket::ContinueHandshake()
01:31:31	Trace:	CTlsSocket::OnSend()
01:31:31	Trace:	CTlsSocket::OnSend()
01:31:31	Trace:	CTlsSocket::OnRead()
01:31:31	Trace:	CFtpControlSocket::OnReceive()
01:31:31	Response:	150 Here comes the directory listing.
01:31:31	Trace:	CFtpControlSocket::TransferParseResponse()
01:31:31	Trace:	  code = 1
01:31:31	Trace:	  state = 4
01:31:31	Trace:	CFtpControlSocket::SendNextCommand()
01:31:31	Trace:	CFtpControlSocket::TransferSend()
01:31:31	Trace:	  state = 5
01:31:31	Trace:	CTlsSocket::OnRead()
01:31:31	Trace:	CTlsSocket::ContinueHandshake()
01:31:31	Trace:	CTlsSocket::OnRead()
01:31:31	Trace:	CTlsSocket::ContinueHandshake()
01:31:31	Trace:	CTlsSocket::OnRead()
01:31:31	Trace:	CTlsSocket::ContinueHandshake()
01:31:31	Trace:	CTlsSocket::OnRead()
01:31:31	Trace:	CTlsSocket::ContinueHandshake()
01:31:31	Trace:	TLS Handshake successful
01:31:31	Trace:	Cipher: AES-128-CBC, MAC: SHA1
01:31:31	Trace:	CTransferSocket::OnConnect
01:31:31	Trace:	CTlsSocket::OnRead()
01:31:31	Trace:	CTransferSocket::OnReceive(), m_transferMode=0
01:31:31	Trace:	CTransferSocket::TransferEnd(1)
01:31:31	Trace:	CFtpControlSocket::TransferEnd()
01:31:31	Trace:	CTlsSocket::OnRead()
01:31:31	Trace:	CFtpControlSocket::OnReceive()
01:31:31	Response:	226 Directory send OK.
01:31:31	Trace:	CFtpControlSocket::TransferParseResponse()
01:31:31	Trace:	  code = 2
01:31:31	Trace:	  state = 7
01:31:31	Trace:	CFtpControlSocket::ResetOperation(0)
01:31:31	Trace:	CControlSocket::ResetOperation(0)
01:31:31	Trace:	CFtpControlSocket::ParseSubcommandResult(0)
01:31:31	Trace:	CFtpControlSocket::ListSubcommandResult()
01:31:31	Trace:	  state = 3
01:31:31	Trace:	CFtpControlSocket::SendNextCommand()
01:31:31	Trace:	CFtpControlSocket::ListSend()
01:31:31	Trace:	  state = 4
01:31:31	Status:	Calculating timezone offset of server...
01:31:31	Command:	MDTM gparted-live-0.9.0-7.iso
01:31:31	Trace:	CTlsSocket::OnRead()
01:31:31	Trace:	CFtpControlSocket::OnReceive()
01:31:31	Response:	213 20120522012936
01:31:31	Trace:	CFtpControlSocket::ListParseResponse()
01:31:31	Status:	Timezone offsets: Server: 0 seconds. Local: 7200 seconds. Difference: 7200 seconds.
01:31:31	Trace:	CFtpControlSocket::ResetOperation(0)
01:31:31	Trace:	CControlSocket::ResetOperation(0)
01:31:31	Status:	Directory listing successful
01:31:31	Trace:	CFileZillaEnginePrivate::ResetOperation(0)
01:31:38	Status:	Resolving address of store2.du1.cesnet.cz
01:31:38	Status:	Connecting to xxxxxxxxxxxx:21...
01:31:38	Status:	Connection established, waiting for welcome message...
01:31:38	Trace:	CFtpControlSocket::OnReceive()
01:31:38	Response:	220 (vsFTPd 2.3.2)
01:31:38	Trace:	CFtpControlSocket::SendNextCommand()
01:31:38	Command:	AUTH TLS
01:31:38	Trace:	CFtpControlSocket::OnReceive()
01:31:38	Response:	234 Proceed with negotiation.
01:31:38	Status:	Initializing TLS...
01:31:38	Trace:	CTlsSocket::Handshake()
01:31:38	Trace:	CTlsSocket::ContinueHandshake()
01:31:38	Trace:	CTlsSocket::OnSend()
01:31:38	Trace:	CTlsSocket::OnRead()
01:31:38	Trace:	CTlsSocket::ContinueHandshake()
01:31:38	Trace:	CTlsSocket::OnRead()
01:31:38	Trace:	CTlsSocket::ContinueHandshake()
01:31:38	Trace:	CTlsSocket::OnRead()
01:31:38	Trace:	CTlsSocket::ContinueHandshake()
01:31:38	Trace:	TLS Handshake successful
01:31:38	Trace:	Cipher: AES-128-CBC, MAC: SHA1
01:31:38	Status:	Verifying certificate...
01:31:38	Trace:	CFtpControlSocket::SendNextCommand()
01:31:38	Command:	USER xxxxxxxxxxx
01:31:38	Status:	TLS/SSL connection established.
01:31:38	Trace:	CTlsSocket::OnRead()
01:31:38	Trace:	CFtpControlSocket::OnReceive()
01:31:38	Response:	331 Please specify the password.
01:31:38	Trace:	CFtpControlSocket::SendNextCommand()
01:31:38	Command:	PASS *********
01:31:38	Trace:	CTlsSocket::OnRead()
01:31:38	Trace:	CFtpControlSocket::OnReceive()
01:31:38	Response:	230 Login successful.
01:31:38	Trace:	CFtpControlSocket::SendNextCommand()
01:31:38	Command:	OPTS UTF8 ON
01:31:38	Trace:	CTlsSocket::OnRead()
01:31:38	Trace:	CFtpControlSocket::OnReceive()
01:31:38	Response:	200 Always in UTF8 mode.
01:31:38	Trace:	CFtpControlSocket::SendNextCommand()
01:31:38	Command:	PBSZ 0
01:31:38	Trace:	CTlsSocket::OnRead()
01:31:38	Trace:	CFtpControlSocket::OnReceive()
01:31:38	Response:	200 PBSZ set to 0.
01:31:38	Trace:	CFtpControlSocket::SendNextCommand()
01:31:38	Command:	PROT P
01:31:38	Trace:	CTlsSocket::OnRead()
01:31:38	Trace:	CFtpControlSocket::OnReceive()
01:31:38	Response:	200 PROT now Private.
01:31:38	Status:	Connected
01:31:38	Trace:	CFtpControlSocket::ResetOperation(0)
01:31:38	Trace:	CControlSocket::ResetOperation(0)
01:31:38	Trace:	CFileZillaEnginePrivate::ResetOperation(0)
01:31:38	Trace:	CFtpControlSocket::FileTransfer()
01:31:38	Status:	Starting upload of /home/keruom/gparted-live-0.9.0-7.iso
01:31:38	Trace:	CFtpControlSocket::SendNextCommand()
01:31:38	Trace:	CFtpControlSocket::ChangeDirSend()
01:31:38	Command:	CWD /
01:31:38	Trace:	CTlsSocket::OnRead()
01:31:38	Trace:	CFtpControlSocket::OnReceive()
01:31:38	Response:	250 Directory successfully changed.
01:31:38	Trace:	CFtpControlSocket::ResetOperation(0)
01:31:38	Trace:	CControlSocket::ResetOperation(0)
01:31:38	Trace:	CFtpControlSocket::ParseSubcommandResult(0)
01:31:38	Trace:	FileTransferSubcommandResult()
01:31:39	Trace:	CFtpControlSocket::SendNextCommand()
01:31:39	Trace:	FileTransferSend()
01:31:39	Trace:	CFtpControlSocket::SendNextCommand()
01:31:39	Trace:	CFtpControlSocket::TransferSend()
01:31:39	Trace:	  state = 1
01:31:39	Command:	TYPE I
01:31:39	Trace:	CTlsSocket::OnRead()
01:31:39	Trace:	CFtpControlSocket::OnReceive()
01:31:39	Response:	200 Switching to Binary mode.
01:31:39	Trace:	CFtpControlSocket::TransferParseResponse()
01:31:39	Trace:	  code = 2
01:31:39	Trace:	  state = 1
01:31:39	Trace:	CFtpControlSocket::SendNextCommand()
01:31:39	Trace:	CFtpControlSocket::TransferSend()
01:31:39	Trace:	  state = 2
01:31:39	Command:	PASV
01:31:39	Trace:	CTlsSocket::OnRead()
01:31:39	Trace:	CFtpControlSocket::OnReceive()
01:31:39	Response:	227 Entering Passive Mode (xxxxxxxxxxxxx,38,6).
01:31:39	Trace:	CFtpControlSocket::TransferParseResponse()
01:31:39	Trace:	  code = 2
01:31:39	Trace:	  state = 2
01:31:39	Trace:	CFtpControlSocket::SendNextCommand()
01:31:39	Trace:	CFtpControlSocket::TransferSend()
01:31:39	Trace:	  state = 4
01:31:39	Command:	STOR gparted-live-0.9.0-7.iso
01:31:39	Trace:	CTransferSocket::OnConnect
01:31:39	Trace:	CTlsSocket::Handshake()
01:31:39	Trace:	CTlsSocket::ContinueHandshake()
01:31:39	Trace:	CTlsSocket::OnSend()
01:31:39	Trace:	CTlsSocket::OnSend()
01:31:39	Trace:	CTlsSocket::OnRead()
01:31:39	Trace:	CFtpControlSocket::OnReceive()
01:31:39	Response:	150 Ok to send data.
01:31:39	Trace:	CFtpControlSocket::TransferParseResponse()
01:31:39	Trace:	  code = 1
01:31:39	Trace:	  state = 4
01:31:39	Trace:	CFtpControlSocket::SendNextCommand()
01:31:39	Trace:	CFtpControlSocket::TransferSend()
01:31:39	Trace:	  state = 5
01:31:39	Trace:	CTlsSocket::OnRead()
01:31:39	Trace:	CTlsSocket::ContinueHandshake()
01:31:39	Trace:	CTlsSocket::OnRead()
01:31:39	Trace:	CTlsSocket::ContinueHandshake()
01:31:39	Trace:	CTlsSocket::OnRead()
01:31:39	Trace:	CTlsSocket::ContinueHandshake()
01:31:39	Trace:	TLS Handshake successful
01:31:39	Trace:	Cipher: AES-128-CBC, MAC: SHA1
01:31:39	Trace:	CTransferSocket::OnConnect
01:31:39	Trace:	First EAGAIN in CTransferSocket::OnSend()
01:32:00	Error:	Connection timed out
01:32:00	Trace:	CControlSocket::DoClose(2050)
01:32:00	Trace:	CFtpControlSocket::ResetOperation(2114)
01:32:00	Trace:	CControlSocket::ResetOperation(2114)
01:32:00	Trace:	CFtpControlSocket::ResetOperation(2114)
01:32:00	Trace:	CControlSocket::ResetOperation(2114)
01:32:00	Error:	File transfer failed after transferring 180224 bytes in 21 seconds

Now, the important fact is that I have disabled the "speed limit" feature, thus reatelimit.cpp is not in action. The error EAGAIN was observed in file backend.cpp:43 (function
int CSocketBackend::Write(const void *buffer, unsigned int len, int& error))

The source of the error is tlssocket.cpp:621 (function CTlsSocket::Write(const void *buffer, unsigned int len, int& error)), where one gets GNUTLS_E_AGAIN error. In return, this function set m_lastWriteFailed flag as true (which is important, see below).
I think that until now, it still behaves correctly and I didn't dig into why I got GNUTLS_E_AGAIN error every 180,224 bytes.

The problem is that nobody tries to send the data again! First, in function CTransferSocket::OnSend() in transfersocket.cpp:431, the only action upon EAGAIN error is practically to print the message about the first EAGAIN error and thats it. So this is why we get connection timeout errors.
Furthermore, if you patch the CTransferSocket::OnSend() function to not give up, it will fail in tlssocket.cpp:593, because it is checking whether the m_lastWriteFailed flag is true or not. If true, it just returns EAGAIN ending up in an infinite loop. When I deleted this (useless?) check, the transfer started to work just fine (getting GNU_TLS error regularly, but recovering from it).

I did not try to fully understand the whole error checking/recovering code so some of my thoughts may be wrong, but this should point somebody more familiar with the code to the right place.

Regards
Jiri Horky

comment:5 Changed 7 years ago by Jiri Horky

Hi again,

some more information. As described above, the problem is that filezilla can not recover from GNUTLS_E_AGAIN error.

Apparently, the GNUTLS error only gets triggered in some version of gnutls library. If I try older filezilla (3.3.5.1) with gnutls < 2.12.0 (2.11.7 see note below), it behaves correctly, the same version with gnutls >= 2.12.0. fails as described in comment above.

PS: filezilla 3.5.3 with older gnutls library (2.8.6) fails even to connect because of "gnutls error -50."

Please note gnutls-2.12.0 downloaded from official homepage says about itself it is 2.11.7.

comment:6 Changed 7 years ago by Alexander Schuch

Status: newmoreinfo

For GnuTLS error -12, please have a look at #7873.

Beside that, do you still have the mentioned problem in current version of FileZilla?

comment:7 Changed 7 years ago by Jiri Horky

Status: moreinfonew

Hi,

the problem seems to be fixed in 3.6.0.2 (and I also tried 3.6.0.1 which is affected).

Jiri Horky

comment:8 Changed 7 years ago by Alexander Schuch

Resolution: fixed
Status: newclosed
Note: See TracTickets for help on using tickets.