problem for process queue use multiple connectios with TLS

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

Moderator: Project members

Post Reply
Message
Author
twu2
425 Can't open data connection
Posts: 45
Joined: 2005-02-26 16:54

problem for process queue use multiple connectios with TLS

#1 Post by twu2 » 2006-06-16 07:41

FileZilla 2.2.24b
1. add 1 file to queue from server #1 with TLS, then stop it.
2. add 1 file to queue from server #2 (or same server as server #1) with TLS, then stop it.
3. we've 2 files in queue, exit FileZilla
4. start FileZilla again, choose 'use multiple connections' from queue menu.
5. start to process queue.
6. 2nd connection will get an error for 'm_pSslLayer not initialized'

reset the error status and try it again, it will work.

it fails only when 2 TLS/SSL connect, in initialize state.

I add some trace message to FtpControlSocket.cpp, get the following log:

Code: Select all

Trace:	FtpControlSocket.cpp(215): twu2: in Connect   caller=0x00aa85b4
Trace:	FtpControlSocket.cpp(234): twu2: change nOpMode to CSMODE_CONNECT   caller=0x00aa85b4
Trace:	FtpControlSocket.cpp(255): twu2: AddLayer   caller=0x00aa85b4
Trace:	FtpControlSocket.cpp(269): twu2: after AddLayer   caller=0x00aa85b4
Status:	Connecting to mail.teatime.com.tw ...
Trace:	FtpControlSocket.cpp(413): twu2: change OpState to CONNECT_SSL_INIT   caller=0x00aa85b4
Trace:	FtpControlSocket.cpp(416): twu2: try Connect   caller=0x00aa85b4
Trace:	FtpControlSocket.cpp(215): twu2: in Connect   caller=0x00aa8014
Trace:	FtpControlSocket.cpp(234): twu2: change nOpMode to CSMODE_CONNECT   caller=0x00aa8014
Trace:	FtpControlSocket.cpp(255): twu2: AddLayer   caller=0x00aa8014
Trace:	FtpControlSocket.cpp(269): twu2: after AddLayer   caller=0x00aa8014
Status:	Connecting to fw2.teatime.com.tw ...
Trace:	FtpControlSocket.cpp(413): twu2: change OpState to CONNECT_SSL_INIT   caller=0x00aa8014
Trace:	FtpControlSocket.cpp(416): twu2: try Connect   caller=0x00aa8014
Trace:	FtpControlSocket.cpp(428): twu2: end of Connect   caller=0x00aa8014
Trace:	FtpControlSocket.cpp(1018): OnConnect(0)  OpMode=1 OpState=-8   caller=0x00aa8014
Status:	Connected with fw2.teatime.com.tw. Waiting for welcome message...
Trace:	FtpControlSocket.cpp(428): twu2: end of Connect   caller=0x00aa85b4
Trace:	FtpControlSocket.cpp(5168): m_pSslLayer changed state from 0 to 1   caller=0x00aa85b4
Trace:	FtpControlSocket.cpp(5168): m_pSslLayer changed state from 1 to 2   caller=0x00aa85b4
Trace:	FtpControlSocket.cpp(5168): m_pSslLayer changed state from 2 to 4   caller=0x00aa85b4
Trace:	FtpControlSocket.cpp(1018): OnConnect(0)  OpMode=1 OpState=-8   caller=0x00aa85b4
Status:	Connected with mail.teatime.com.tw, negotiating SSL connection...
Trace:	FtpControlSocket.cpp(840): OnReceive(0)  OpMode=1 OpState=-8   caller=0x00aa85b4
Response:	220---------- Welcome to Pure-FTPd [privsep] [TLS] ----------
Response:	220-You are user number 2 of 50 allowed.
Response:	220-Local time is now 15:24. Server port: 21.
Response:	220 You will be disconnected after 15 minutes of inactivity.
Trace:	FtpControlSocket.cpp(457): twu2: for CONNECT_SSL_INIT   caller=0x00aa85b4
Trace:	FtpControlSocket.cpp(465): twu2: before AUTH TLS   caller=0x00aa85b4
Command:	AUTH TLS
Trace:	FtpControlSocket.cpp(471): twu2: change to CONNECT_SSL_NEGOTIATE   caller=0x00aa85b4
Trace:	FtpControlSocket.cpp(840): OnReceive(0)  OpMode=1 OpState=-9   caller=0x00aa85b4
Response:	234 AUTH TLS OK.
Trace:	FtpControlSocket.cpp(477): twu2: for CONNECT_SSL_NEGOTIATE   caller=0x00aa85b4
Trace:	FtpControlSocket.cpp(487): twu2: CONNECT_SSL_NEGOTIATE checl SSL #2   caller=0x00aa85b4
Trace:	FtpControlSocket.cpp(495): twu2: call SSL Connection   caller=0x00aa85b4
Trace:	FtpControlSocket.cpp(840): OnReceive(0)  OpMode=1 OpState=-8   caller=0x00aa8014
Response:	220---------- Welcome to Pure-FTPd [privsep] [TLS] ----------
Response:	220-You are user number 1 of 50 allowed.
Response:	220-Local time is now 15:24. Server port: 21.
Response:	220 You will be disconnected after 15 minutes of inactivity.
Trace:	FtpControlSocket.cpp(457): twu2: for CONNECT_SSL_INIT   caller=0x00aa8014
Trace:	FtpControlSocket.cpp(465): twu2: before AUTH TLS   caller=0x00aa8014
Command:	AUTH TLS
Trace:	FtpControlSocket.cpp(471): twu2: change to CONNECT_SSL_NEGOTIATE   caller=0x00aa8014
Trace:	FtpControlSocket.cpp(840): OnReceive(0)  OpMode=1 OpState=-10   caller=0x00aa85b4
Trace:	FtpControlSocket.cpp(840): OnReceive(0)  OpMode=1 OpState=-9   caller=0x00aa8014
Response:	234 AUTH TLS OK.
Trace:	FtpControlSocket.cpp(477): twu2: for CONNECT_SSL_NEGOTIATE   caller=0x00aa8014
Trace:	FtpControlSocket.cpp(487): twu2: CONNECT_SSL_NEGOTIATE checl SSL #2   caller=0x00aa8014
Trace:	FtpControlSocket.cpp(490): twu2: m_pSslLayer not initialized #2   caller=0x00aa8014
Error:	Internal error: m_pSslLayer not initialized #2
Trace:	FtpControlSocket.cpp(1157): DoClose(8192)  OpMode=1 OpState=-9   caller=0x00aa8014
Trace:	FtpControlSocket.cpp(4003): ResetOperation(12292)  OpMode=1 OpState=-9   caller=0x00aa8014
Error:	Unable to connect!
Trace:	SSL_connect: SSLv3 read server hello A
Trace:	SSL_connect: SSLv3 read server certificate A
Trace:	SSL_connect: SSLv3 read server done A
Trace:	SSL_connect: SSLv3 write client key exchange A
Trace:	SSL_connect: SSLv3 write change cipher spec A
Trace:	SSL_connect: SSLv3 write finished A
Trace:	SSL_connect: SSLv3 flush data
Trace:	SSL_connect: SSLv3 read finished A
Trace:	Using TLSv1, cipher TLSv1/SSLv3: AES256-SHA, 1024 bit RSA
Status:	SSL connection established. Waiting for welcome message...
Command:	USER tommy
Trace:	FtpControlSocket.cpp(840): OnReceive(0)  OpMode=1 OpState=0   caller=0x00aa85b4
Response:	331 User tommy OK. Password required

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

#2 Post by botg » 2006-06-16 09:00

Is this a custom version of FileZilla? The log looks very strange.

twu2
425 Can't open data connection
Posts: 45
Joined: 2005-02-26 16:54

#3 Post by twu2 » 2006-06-16 09:23

yes, I add some messages, try to trace this problem.
I just try it again, use original 2.2.24b from sourceforge site, same result, here is the log:

Code: Select all

Status:	Connecting to mail.teatime.com.tw ...
Status:	Connecting to mail.teatime.com.tw ...
Trace:	FtpControlSocket.cpp(990): OnConnect(0)  OpMode=1 OpState=-8   caller=0x00aa8344
Status:	Connected with mail.teatime.com.tw. Waiting for welcome message...
Trace:	FtpControlSocket.cpp(5140): m_pSslLayer changed state from 0 to 1   caller=0x00aa88e4
Trace:	FtpControlSocket.cpp(5140): m_pSslLayer changed state from 1 to 2   caller=0x00aa88e4
Trace:	FtpControlSocket.cpp(5140): m_pSslLayer changed state from 2 to 4   caller=0x00aa88e4
Trace:	FtpControlSocket.cpp(990): OnConnect(0)  OpMode=1 OpState=-8   caller=0x00aa88e4
Status:	Connected with mail.teatime.com.tw, negotiating SSL connection...
Trace:	FtpControlSocket.cpp(812): OnReceive(0)  OpMode=1 OpState=-8   caller=0x00aa8344
Trace:	FtpControlSocket.cpp(812): OnReceive(0)  OpMode=1 OpState=-8   caller=0x00aa88e4
Response:	220---------- Welcome to Pure-FTPd [privsep] [TLS] ----------
Response:	220-You are user number 2 of 50 allowed.
Response:	220-Local time is now 17:19. Server port: 21.
Response:	220 You will be disconnected after 15 minutes of inactivity.
Command:	AUTH TLS
Response:	220---------- Welcome to Pure-FTPd [privsep] [TLS] ----------
Response:	220-You are user number 1 of 50 allowed.
Response:	220-Local time is now 17:19. Server port: 21.
Response:	220 You will be disconnected after 15 minutes of inactivity.
Command:	AUTH TLS
Trace:	FtpControlSocket.cpp(812): OnReceive(0)  OpMode=1 OpState=-9   caller=0x00aa88e4
Response:	234 AUTH TLS OK.
Trace:	FtpControlSocket.cpp(812): OnReceive(0)  OpMode=1 OpState=-9   caller=0x00aa8344
Response:	234 AUTH TLS OK.
Error:	Internal error: m_pSslLayer not initialized
Trace:	FtpControlSocket.cpp(1129): DoClose(8192)  OpMode=1 OpState=-9   caller=0x00aa8344
Trace:	FtpControlSocket.cpp(3975): ResetOperation(12292)  OpMode=1 OpState=-9   caller=0x00aa8344
Error:	Unable to connect!
Trace:	FtpControlSocket.cpp(812): OnReceive(0)  OpMode=1 OpState=-10   caller=0x00aa88e4
Trace:	SSL_connect: SSLv3 read server hello A
Trace:	SSL_connect: SSLv3 read server certificate A
Trace:	SSL_connect: SSLv3 read server done A
Trace:	SSL_connect: SSLv3 write client key exchange A
Trace:	SSL_connect: SSLv3 write change cipher spec A
Trace:	SSL_connect: SSLv3 write finished A
Trace:	SSL_connect: SSLv3 flush data
Trace:	SSL_connect: SSLv3 read finished A
Trace:	Using TLSv1, cipher TLSv1/SSLv3: AES256-SHA, 1024 bit RSA
Status:	SSL connection established. Waiting for welcome message...
Command:	USER tommy
Trace:	FtpControlSocket.cpp(812): OnReceive(0)  OpMode=1 OpState=0   caller=0x00aa88e4
Response:	331 User tommy OK. Password required

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

#4 Post by botg » 2006-06-16 09:46

Which server are you using?

twu2
425 Can't open data connection
Posts: 45
Joined: 2005-02-26 16:54

#5 Post by twu2 » 2006-06-16 10:56

botg wrote:Which server are you using?
pure-ftpd.

either from same servers or from two different servers, same result. (but all servers use pure-ftpd.)

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

#6 Post by botg » 2006-06-16 14:43

What happens if you try to connect to the server simultaneously from two different insteances of FileZilla?

Add your server to the site manager, give it a simple name (e.g. foo). Start the windows command prompt and go to the directory where FileZilla is installed.
Then type

Code: Select all

filezilla -s foo && filezilla -s foo

twu2
425 Can't open data connection
Posts: 45
Joined: 2005-02-26 16:54

#7 Post by twu2 » 2006-06-17 01:32

botg wrote:Then type

Code: Select all

filezilla -s foo && filezilla -s foo
same result. one success, one fail (same error).

twu2
425 Can't open data connection
Posts: 45
Joined: 2005-02-26 16:54

#8 Post by twu2 » 2006-06-17 05:18

I think I found the reason for this problem.

This problem only happen for we setup a limit port range. When FZ try to call CFtpControlSocket::Create(), FZ will get a same port here. so Bind() fail, then Close(), every thing close, lost layer setting for this socket, then try next port, connect ok, but no any ssl layer.

I saw a rand() here to choose the port, but it still get the same number. (because we call srand() in the same time? the seed is same?)

how to fix it?

1. maybe force each instance to use different seed? time+instance id? this may solve the problem when we start the connect at same time, but it will be a problem, it's possible, we still choose one source port already used by other session... same result.

2. do not remove layer (and other setting) when we fail to bind the socket, if we need to try it again? or re-initialize every thing before we try another port?

2nd one will be better.

here is my ugly patch for 2nd solution, it work for me.

Code: Select all

diff -Nur source.orig/FtpControlSocket.cpp source/FtpControlSocket.cpp
--- source.orig/FtpControlSocket.cpp	Fri May 26 14:24:30 2006
+++ source/FtpControlSocket.cpp	Sat Jun 17 13:01:58 2006
@@ -198,7 +198,7 @@
 #define CONNECT_OPTSUTF8 -15
 #define CONNECT_CLNT -16
 
-void CFtpControlSocket::Connect(t_server &server)
+BOOL CFtpControlSocket::InitConnect(t_server &server)
 {
 	USES_CONVERSION;
 
@@ -219,14 +219,14 @@
 		if (!m_Operation.nOpMode)
 			m_Operation.nOpMode = CSMODE_CONNECT;
 		DoClose(FZ_REPLY_CRITICALERROR);
-		return;
+		return FALSE;
 	}
 	if (m_Operation.nOpMode)
 	{
 		ShowStatus(_T("Internal error: m_Operation.nOpMode not zero in Connect"), 1);
 		m_Operation.nOpMode = CSMODE_CONNECT;
 		DoClose(FZ_REPLY_CRITICALERROR);
-		return;
+		return FALSE;
 	}
 
 	m_Operation.nOpMode = CSMODE_CONNECT;
@@ -235,13 +235,13 @@
 	{
 		ShowStatus(_T("Internal error: m_pSslLayer not zero in Connect"), 1);
 		DoClose(FZ_REPLY_CRITICALERROR);
-		return;
+		return FALSE;
 	}
 	if (m_pProxyLayer)
 	{
 		ShowStatus(_T("Internal error: m_pProxyLayer not zero in Connect"), 1);
 		DoClose(FZ_REPLY_CRITICALERROR);
-		return;
+		return FALSE;
 	}
 
 	if (server.nServerType & FZ_SERVERTYPE_LAYER_SSL_IMPLICIT ||
@@ -328,11 +328,20 @@
 		{
 			ShowStatus(_T("Unable to initialize GSS api"), 1);
 			DoClose(FZ_REPLY_CRITICALERROR);
-			return;
+			return FALSE;
 		}
 	}
 	m_Operation.nOpState = m_pGssLayer?CONNECT_GSS_INIT:CONNECT_INIT;
 	m_Operation.nOpMode = CSMODE_CONNECT;
+	return TRUE;
+}
+
+void CFtpControlSocket::Connect(t_server &server)
+{
+	USES_CONVERSION;
+
+	m_server = server;
+	if (!InitConnect(server)) return;
 	
 	if (!Create())
 	{
@@ -3964,6 +3973,8 @@
 				ShowStatus(IDS_ERRORMSG_CANTCREATEDUETOPORTRANGE,1);
 				return FALSE;
 			}
+			m_Operation.nOpMode = 0;
+			if (!InitConnect(m_server)) return FALSE;
 		}
 	}
 	return TRUE;
diff -Nur source.orig/FtpControlSocket.h source/FtpControlSocket.h
--- source.orig/FtpControlSocket.h	Fri May 26 14:19:06 2006
+++ source/FtpControlSocket.h	Sat Jun 17 12:57:15 2006
@@ -49,6 +49,8 @@
 
 // �berschreibungen
 public:
+	t_server m_server;
+	BOOL InitConnect(t_server &server);
 	virtual void Connect(t_server &server);
 	virtual void OnTimer();
 	virtual BOOL IsReady();

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

#9 Post by botg » 2006-06-17 08:56

Thanks for the patch. I've committed a slightly modified version to CVS.

Post Reply