Our Products:   CompleteFTP  edtFTPnet/Free  edtFTPnet/PRO  edtFTPj/Free  edtFTPj/PRO
0 votes
8k views
in .NET FTP by (120 points)
Since upgrading to SP1 on Win2003 Server I have experienced an intermittent problem where by the code execution will just hang. No exception will be thrown, and code will not not continue to run.

The application is a .net windows service that uses the thread pool i.e. QueueUserWorkItem at periodic intervals to download files from an FTP service. Only 1 thread that is using the FTP component is created at once, and the system waits until that thread has completed its work before it spawns another.

I have done extensive tracing in the edtFTPnet component to find where it stop running and have found the following:

The application calls FTPClient.Dir() and the following stack trace is created:
FTPClient.Dir()
FTPClient.Dir (string dirname, bool full)
StreamReader input = new StreamReader(data.DataStream);
FTPActiveDataSocket.DataStream
FTPActiveDataSocket.AcceptConnection
acceptedSock = sock.Accept();

The code does not go past the last line above.

The connection mode is FTPConnectMode.ACTIVE and the timeout is set to 10000 milliseconds.

This problem does not occur on Win2003 server that does not have SP1.

Please could you help, thanks?

I would be happy to do any more tracing / debugging or help in any way that I can.

Thank you in advance

10 Answers

0 votes
by
I'm having the same problem running under XP Pro SP2. I'm using Active mode ftp with a timeout of 10000ms. I'm doing a Dir() and the app just hangs.
0 votes
by (162k points)
Have emailed you with a fix for this to try out.

I'm having the same problem running under XP Pro SP2. I'm using Active mode ftp with a timeout of 10000ms. I'm doing a Dir() and the app just hangs.
0 votes
by (700 points)
I tried out the fixed dll that you sent me. It is half way there. I'll try to explain the best that I can. My app is a C# form that allows you to enter in some basic FTP settings (server, username,password,port, active/pasv,active ip/ports,remote folder, local folder,etc.) Then you click a button and it logs into the server, changes to the remote folder, checks the local folder for any files, and uploads those files to the remote server.

I started using the fix that you sent, and when I run the app and click the "Send" button, the timeout works as it should and I get the following exception and log file:
Exception:
System.IO.IOException: Failed to accept connection within timeout period (25000)
   at al.b(Int32 A_0)
   at h.d()
   at h.e()
   at EnterpriseDT.Net.Ftp.FTPClient.Dir(String dirname, Boolean full)
   at EnterpriseDT.Net.Ftp.FTPClient.Dir()
   at FTPConfig.MainForm.btnTest_Click(Object sender, EventArgs e) in c:\documents and settings\adsi480\desktop\drop box\projects\ftpservice - junk\ftpconfig\mainform.cs:line 921

Log:
INFO [FTPConfig.MainForm] 10 Apr 2006 09:35:35.468 : ActivePortRange = 12000 - 13000
INFO [EnterpriseDT.Net.Ftp.Pro.ProFTPClient] 10 Apr 2006 09:35:35.484 : Licence expiry date: 5/27/2006
INFO [EnterpriseDT.Net.Ftp.Pro.ProFTPClient] 10 Apr 2006 09:35:35.484 : Trial license
DEBUG [EnterpriseDT.Net.Ftp.Pro.ProFTPClient] 10 Apr 2006 09:35:35.484 : Connecting to ftpserver:69
DEBUG [EnterpriseDT.Net.Ftp.Pro.ProFTPClient] 10 Apr 2006 09:35:44.359 : ftpserver resolved to 192.168.4.200
DEBUG [b8] 10 Apr 2006 09:35:44.375 : Connecting directly to ftp-server 192.168.4.200:69
DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 10 Apr 2006 09:35:44.515 : 220-Boz's FTP Server
DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 10 Apr 2006 09:35:44.703 : 220 FileZilla Server version 0.9.14a beta
DEBUG [b8] 10 Apr 2006 09:35:44.703 : Created control-socket: ImplicitFTPS=False, SocksContext=, RemoteHost=0, controlPort=192.168.4.200, timeout=69, CompatibilityFlags=0
DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 10 Apr 2006 09:35:44.703 : ---> USER kioware
DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 10 Apr 2006 09:35:44.765 : 331 Password required for kioware
DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 10 Apr 2006 09:35:44.781 : ---> PASS ********
DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 10 Apr 2006 09:35:44.828 : 230 Logged on
DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 10 Apr 2006 09:35:44.828 : ---> TYPE I
DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 10 Apr 2006 09:35:44.890 : 200 Type set to I
DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 10 Apr 2006 09:35:44.890 : ---> CWD FTP Test/SubFolder/
DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 10 Apr 2006 09:35:44.953 : 250 CWD successful. "/FTP Test/SubFolder" is current directory.
DEBUG [b8] 10 Apr 2006 09:35:44.953 : Creating active data socket on port 12000
DEBUG [b8] 10 Apr 2006 09:35:44.953 : Binding 192.168.7.193
INFO [EnterpriseDT.Net.Ftp.FTPControlSocket] 10 Apr 2006 09:35:44.968 : Forcing use of fixed IP for PORT command
DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 10 Apr 2006 09:35:44.968 : ---> PORT 207,181,186,233,46,224
DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 10 Apr 2006 09:35:45.031 : 200 Port command successful
DEBUG [h] 10 Apr 2006 09:35:45.031 : Created active data-socket: Protocol=b, SocksConnector=, CompatibilityFlags=0
DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 10 Apr 2006 09:35:45.031 : Using active port range
DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 10 Apr 2006 09:35:45.031 : Next active port will be: 12001
DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 10 Apr 2006 09:35:45.031 : ---> NLST
DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 10 Apr 2006 09:35:45.093 : 150 Opening data channel for directory list.
DEBUG [h] 10 Apr 2006 09:35:45.093 : Awaiting a direct connection on active data-channel.
WARN [EnterpriseDT.Net.Ftp.FTPClient] 10 Apr 2006 09:36:10.109 : Caught exception closing data socket : Object reference not set to an instance of an object.
   at h.a()
   at h.c()
   at EnterpriseDT.Net.Ftp.FTPClient.a()
DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 10 Apr 2006 09:36:35.562 : ---> QUIT
DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 10 Apr 2006 09:36:35.562 : 425 Can't open data connection.

This all is fine. The timeout works and the log makes sense. Except this line has me a little worried:
WARN [EnterpriseDT.Net.Ftp.FTPClient] 10 Apr 2006 09:36:10.109 : Caught exception closing data socket : Object reference not set to an instance of an object.
   at h.a()
   at h.c()
   at EnterpriseDT.Net.Ftp.FTPClient.a() 

After clicking the button once and getting that failure (as expected), I click the button again. This time, I get a completely different log and execption, and I think it is related to that one entry in the log file that I referred to just above. Here is the exception and log from the second and all subsequent button clicks:
Exception:
System.Net.Sockets.SocketException: Only one usage of each socket address (protocol/network address/port) is normally permitted
   at System.Net.Sockets.Socket.Bind(EndPoint localEP)
   at ax.b(EndPoint A_0)
   at al.a(EndPoint A_0)
   at b8.a(Int32 A_0)
   at EnterpriseDT.Net.Ftp.FTPControlSocket.CreateDataSocketActive()
   at EnterpriseDT.Net.Ftp.FTPControlSocket.CreateDataSocket(FTPConnectMode connectMode)
   at EnterpriseDT.Net.Ftp.FTPClient.Dir(String dirname, Boolean full)
   at EnterpriseDT.Net.Ftp.FTPClient.Dir()
   at FTPConfig.MainForm.btnTest_Click(Object sender, EventArgs e) in c:\documents and settings\adsi480\desktop\drop box\projects\ftpservice - junk\ftpconfig\mainform.cs:line 921

Log:
INFO [FTPConfig.MainForm] 10 Apr 2006 09:37:12.515 : ActivePortRange = 12000 - 13000
INFO [EnterpriseDT.Net.Ftp.Pro.ProFTPClient] 10 Apr 2006 09:37:12.515 : Licence expiry date: 5/27/2006
INFO [EnterpriseDT.Net.Ftp.Pro.ProFTPClient] 10 Apr 2006 09:37:12.515 : Trial license
DEBUG [EnterpriseDT.Net.Ftp.Pro.ProFTPClient] 10 Apr 2006 09:37:12.515 : Connecting to ftpserver:69
DEBUG [EnterpriseDT.Net.Ftp.Pro.ProFTPClient] 10 Apr 2006 09:37:18.375 : ftpserver resolved to 192.168.4.200
DEBUG [b8] 10 Apr 2006 09:37:18.375 : Connecting directly to ftp-server 192.168.4.200:69
DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 10 Apr 2006 09:37:18.500 : 220-Boz's FTP Server
DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 10 Apr 2006 09:37:18.750 : 220 FileZilla Server version 0.9.14a beta
DEBUG [b8] 10 Apr 2006 09:37:18.750 : Created control-socket: ImplicitFTPS=False, SocksContext=, RemoteHost=0, controlPort=192.168.4.200, timeout=69, CompatibilityFlags=0
DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 10 Apr 2006 09:37:18.750 : ---> USER kioware
DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 10 Apr 2006 09:37:18.812 : 331 Password required for kioware
DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 10 Apr 2006 09:37:18.812 : ---> PASS ********
DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 10 Apr 2006 09:37:18.875 : 230 Logged on
DEBUG [EnterpriseDT.Net.Ft
0 votes
by (700 points)
The most recent updated dll that was emailed to me worked. Thanks for all of your help and support. Support is a key factor in making a great product, and you really came through for me. Thanks again.
0 votes
by (162k points)
Cheers, thanks for testing it out. We will be incorporating our fixes into the next official release due out very soon.

The most recent updated dll that was emailed to me worked. Thanks for all of your help and support. Support is a key factor in making a great product, and you really came through for me. Thanks again.
0 votes
by (700 points)
Ok, looks like I lied about this working. It seems to be broken again. The log file looks almost identical to the last one that I posted except this time instead of the WARN line about the socket null reference, I just have a DEBUG line that says "Attempt to close unconnected active data-channel." Here are the details:

First attempt to connect using active mode. This connects successfully and then disconnects.
    LOG FILE:INFO [FTPConfig.MainForm] 18 Apr 2006 10:52:05.575 : ActivePortRange = 12000 - 13000 INFO [EnterpriseDT.Net.Ftp.Pro.ProFTPClient] 18 Apr 2006 10:52:05.585 : Licence expiry date: 6/1/2006 INFO [EnterpriseDT.Net.Ftp.Pro.ProFTPClient] 18 Apr 2006 10:52:05.585 : Trial license DEBUG [EnterpriseDT.Net.Ftp.Pro.ProFTPClient] 18 Apr 2006 10:52:05.585 : Connecting to nighthawk:21 DEBUG [EnterpriseDT.Net.Ftp.Pro.ProFTPClient] 18 Apr 2006 10:52:05.585 : nighthawk resolved to 192.168.7.193 DEBUG [b8] 18 Apr 2006 10:52:05.595 : Connecting directly to ftp-server 192.168.7.193:21 DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 18 Apr 2006 10:52:05.625 : 220-FileZilla Server version 0.9.14a beta DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 18 Apr 2006 10:52:05.625 : 220-written by Tim Kosse (Tim.Kosse@gmx.de) DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 18 Apr 2006 10:52:05.625 : 220 Please visit http://sourceforge.net/projects/filezilla/ DEBUG [b8] 18 Apr 2006 10:52:05.625 : Created control-socket: ImplicitFTPS=False, SocksContext=, RemoteHost=0, controlPort=192.168.7.193, timeout=21, CompatibilityFlags=0 DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 18 Apr 2006 10:52:05.625 : ---> USER bbosley DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 18 Apr 2006 10:52:05.625 : 331 Password required for bbosley DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 18 Apr 2006 10:52:05.625 : ---> PASS ******** DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 18 Apr 2006 10:52:05.625 : 230 Logged on DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 18 Apr 2006 10:52:05.625 : ---> TYPE I DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 18 Apr 2006 10:52:05.635 : 200 Type set to I DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 18 Apr 2006 10:52:05.635 : ---> CWD ./ DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 18 Apr 2006 10:52:05.635 : 250 CWD successful. "/" is current directory. DEBUG [b8] 18 Apr 2006 10:52:05.635 : Creating active data socket on port 12000 DEBUG [b8] 18 Apr 2006 10:52:05.635 : Binding 192.168.7.4 DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 18 Apr 2006 10:52:05.645 : ---> PORT 192,168,7,4,46,224 DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 18 Apr 2006 10:52:05.665 : 200 Port command successful DEBUG [h] 18 Apr 2006 10:52:05.665 : Created active data-socket: Protocol=b, SocksConnector=, CompatibilityFlags=0 DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 18 Apr 2006 10:52:05.665 : Next active port will be: 12001 DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 18 Apr 2006 10:52:05.665 : ---> NLST DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 18 Apr 2006 10:52:05.675 : 150 Opening data channel for directory list. DEBUG [h] 18 Apr 2006 10:52:05.675 : Awaiting a direct connection on active data-channel. DEBUG [h] 18 Apr 2006 10:52:05.675 : Direct connection on active data-channel established. DEBUG [h] 18 Apr 2006 10:52:05.685 : Attempt to close unconnected active data-channel. DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 18 Apr 2006 10:52:05.685 : 226 Transfer OK DEBUG [EnterpriseDT.Net.Ftp.FTPClient] 18 Apr 2006 10:52:05.685 : Found 2 listing lines DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 18 Apr 2006 10:52:05.685 : ---> QUIT
I then try to connect a second time. This time it is unsuccessful and I get an exception.
    LOG FILE:INFO [FTPConfig.MainForm] 18 Apr 2006 10:52:07.378 : ActivePortRange = 12000 - 13000 INFO [EnterpriseDT.Net.Ftp.Pro.ProFTPClient] 18 Apr 2006 10:52:07.378 : Licence expiry date: 6/1/2006 INFO [EnterpriseDT.Net.Ftp.Pro.ProFTPClient] 18 Apr 2006 10:52:07.378 : Trial license DEBUG [EnterpriseDT.Net.Ftp.Pro.ProFTPClient] 18 Apr 2006 10:52:07.378 : Connecting to nighthawk:21 DEBUG [EnterpriseDT.Net.Ftp.Pro.ProFTPClient] 18 Apr 2006 10:52:07.378 : nighthawk resolved to 192.168.7.193 DEBUG [b8] 18 Apr 2006 10:52:07.378 : Connecting directly to ftp-server 192.168.7.193:21 DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 18 Apr 2006 10:52:07.388 : 220-FileZilla Server version 0.9.14a beta DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 18 Apr 2006 10:52:07.388 : 220-written by Tim Kosse (Tim.Kosse@gmx.de) DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 18 Apr 2006 10:52:07.388 : 220 Please visit http://sourceforge.net/projects/filezilla/ DEBUG [b8] 18 Apr 2006 10:52:07.388 : Created control-socket: ImplicitFTPS=False, SocksContext=, RemoteHost=0, controlPort=192.168.7.193, timeout=21, CompatibilityFlags=0 DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 18 Apr 2006 10:52:07.388 : ---> USER bbosley DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 18 Apr 2006 10:52:07.388 : 331 Password required for bbosley DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 18 Apr 2006 10:52:07.388 : ---> PASS ******** DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 18 Apr 2006 10:52:07.388 : 230 Logged on DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 18 Apr 2006 10:52:07.388 : ---> TYPE I DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 18 Apr 2006 10:52:07.388 : 200 Type set to I DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 18 Apr 2006 10:52:07.388 : ---> CWD ./ DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 18 Apr 2006 10:52:07.388 : 250 CWD successful. "/" is current directory. DEBUG [b8] 18 Apr 2006 10:52:07.388 : Creating active data socket on port 12000 DEBUG [b8] 18 Apr 2006 10:52:07.388 : Binding 192.168.7.4 DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 18 Apr 2006 10:52:07.388 : Next active port will be: 12001 DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 18 Apr 2006 10:52:12.074 : ---> QUIT DEBUG [EnterpriseDT.Net.Ftp.FTPControlSocket] 18 Apr 2006 10:52:12.074 : 221 GoodbyeEXCEPTION:System.Net.Sockets.SocketException: Only one usage of each socket address (protocol/network address/port) is normally permitted    at System.Net.Sockets.Socket.Bind(EndPoint localEP)    at ax.b(EndPoint A_0)    at al.a(EndPoint A_0)    at b8.a(Int32 A_0)    at EnterpriseDT.Net.Ftp.FTPControlSocket.CreateDataSocketActive()    at EnterpriseDT.Net.Ftp.FTPControlSocket.CreateDataSocket(FTPConnectMode connectMode)    at EnterpriseDT.Net.Ftp.FTPClient.Dir(String dirname, Boolean full)    at EnterpriseDT.Net.Ftp.FTPClient.Dir()    at FTPConfig.MainForm.btnTest_Click(Object sender, EventArgs e) in c:\documents and settings\adsi480\desktop\drop box\projects\ftpservice - junk\ftpconfig\mainform.cs:line 921

Let me know if you need further details. It seems like the socket still isn't being cleaned up properly.
0 votes
by (162k points)
This error is because the second time you are trying to listen to the same port number, which you can't do immediately - you have to wait till the socket has gone out of TIME_WAIT state.

Probably occurred because you created a new FTPClient instance with the same port range in the second attempt - and so it started off at port 12000 again.

I've made a small fix that maintains the current port number in a static variable, and if port range is used, will avoid using the last used port. I'll email you the details.

Ok, looks like I lied about this working. It seems to be broken again. The log file looks almost identical to the last one that I posted except this time instead of the WARN line about the socket null reference, I just have a DEBUG line that says "Attempt to close unconnected active data-channel."
0 votes
by (700 points)
Bruce,
This still is not working for me. I emailed you the details and my thoughts.
0 votes
by (700 points)
Bruce,
Ok, the dll that you sent me this morning is working with the exception of one very minor thing. I emailed you the details.
0 votes
by (700 points)
Bruce,
Everything seems to be working now. I'll let you know when I'm ready to purchase. Hopefully it won't be too much longer. Thank you very much for all of your great support and fast fixes. Let me know if there is anything else that I can do for you.

Categories

...