UploadFile doesn't terminate until timeout period expires

Question

I've recently started to use edtFTPnet and, generally, it works very well. The problem I'm seeing seems to have been noted in some of the forum topics but I haven't really seen a resolution for this.

When I upload a small file (about 12KB), the UploadFile method returns after uploading the file to the FTP server and I am able to terminate my application properly. When I upload a 10MB file, the file uploads successfully (in less than 2 minutes) but doesn't return from the UploadFile method until the time out value is reached. At this point, I receive a exception:

ERROR [FTPControlSocket] 13 Feb 2011 17:36:13.484 : Read failed ('' read so far)
WARN [FTPClient] 13 Feb 2011 17:36:13.484 : ReadReply failed
WARN [FTPClient] 13 Feb 2011 17:36:13.484 : EnterpriseDT.Net.Ftp.ControlChannelIOException: Unable to read data from the transport connection: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond.
WARN [FTPClient] 13 Feb 2011 17:36:13.484 : at EnterpriseDT.Net.Ftp.FTPControlSocket.ReadLine()
WARN [FTPClient] 13 Feb 2011 17:36:13.484 : at EnterpriseDT.Net.Ftp.FTPControlSocket.ReadReply()
WARN [FTPClient] 13 Feb 2011 17:36:13.484 : at EnterpriseDT.Net.Ftp.FTPClient.ValidateTransfer()

This behavior is very consistent. One thing I notice is that I never receive a 226 Transfer Complete message.

The server I'm connecting to is running IIS6 on Windows Server 2003.

FileZilla has no problems making a connection to the same file, sending the same file and consistently terminating correctly.

Here's what I see in the FTP log:

DEBUG [FTPClient] 13 Feb 2011 19:03:48.750 : Connecting to ftp.reuniondb.com:21
DEBUG [HostNameResolver] 13 Feb 2011 19:03:48.765 : Resolving ftp.reuniondb.com
DEBUG [HostNameResolver] 13 Feb 2011 19:03:48.859 : ftp.reuniondb.com resolved to 69.2.205.51
DEBUG [FTPControlSocket] 13 Feb 2011 19:03:48.859 : Setting socket timeout=1200000
DEBUG [FTPControlSocket] 13 Feb 2011 19:03:48.859 : Command encoding=System.Text.ASCIIEncoding
DEBUG [FTPControlSocket] 13 Feb 2011 19:03:48.859 : StrictReturnCodes=False
DEBUG [FTPControlSocket] 13 Feb 2011 19:03:49.140 : 220-Microsoft FTP Service
DEBUG [FTPControlSocket] 13 Feb 2011 19:03:49.453 : 220 ReunionDB FTP Site
DEBUG [FTPConnection] 13 Feb 2011 19:03:49.453 : Connected to ftp.reuniondb.com (instance=0)
DEBUG [FTPControlSocket] 13 Feb 2011 19:03:49.453 : ---> USER svc_gr
DEBUG [FTPControlSocket] 13 Feb 2011 19:03:49.625 : 331 Password required for svc_gr.
DEBUG [FTPControlSocket] 13 Feb 2011 19:03:49.625 : ---> PASS ********
DEBUG [FTPControlSocket] 13 Feb 2011 19:03:49.781 : 230-Welcome to ReunionDB FTP Site
DEBUG [FTPControlSocket] 13 Feb 2011 19:03:50.046 : 230 User svc_gr logged in.
DEBUG [FTPConnection] 13 Feb 2011 19:03:50.046 : Successfully logged in
DEBUG [FTPControlSocket] 13 Feb 2011 19:03:50.062 : ---> TYPE I
DEBUG [FTPControlSocket] 13 Feb 2011 19:03:50.203 : 200 Type set to I.
DEBUG [FTPControlSocket] 13 Feb 2011 19:03:50.203 : ---> PWD
DEBUG [FTPControlSocket] 13 Feb 2011 19:03:50.375 : 257 "/" is current directory.
DEBUG [FTPControlSocket] 13 Feb 2011 19:03:50.375 : ---> CWD gr/test
DEBUG [FTPControlSocket] 13 Feb 2011 19:03:50.531 : 250 CWD command successful.
DEBUG [FTPControlSocket] 13 Feb 2011 19:03:50.531 : ---> PWD
DEBUG [FTPControlSocket] 13 Feb 2011 19:03:50.718 : 257 "/gr/test" is current directory.
DEBUG [FTPConnection] 13 Feb 2011 19:03:50.718 : UploadFile(C:\Temp\GRI Data\DIY Files\test.7z,test.7z,False)
DEBUG [FTPControlSocket] 13 Feb 2011 19:03:50.718 : ---> PASV
DEBUG [FTPControlSocket] 13 Feb 2011 19:03:50.906 : 227 Entering Passive Mode (69,2,205,51,19,137).
DEBUG [FTPControlSocket] 13 Feb 2011 19:03:50.906 : Server supplied address=69.2.205.51
DEBUG [FTPControlSocket] 13 Feb 2011 19:03:50.906 : Server supplied port=5001
DEBUG [FTPControlSocket] 13 Feb 2011 19:03:50.906 : autoPassiveIPSubstitution=True
DEBUG [FTPControlSocket] 13 Feb 2011 19:03:50.906 : remoteAddr=69.2.205.51
DEBUG [FTPControlSocket] 13 Feb 2011 19:03:50.906 : Substituting server supplied IP (69.2.205.51) with remote host IP (69.2.205.51)
DEBUG [FTPControlSocket] 13 Feb 2011 19:03:50.906 : NewPassiveDataSocket(69.2.205.51,5001)
DEBUG [FTPControlSocket] 13 Feb 2011 19:03:51.062 : ---> STOR test.7z
DEBUG [FTPControlSocket] 13 Feb 2011 19:03:51.218 : 125 Data connection already open; Transfer starting.
DEBUG [FTPClient] 13 Feb 2011 19:06:46.781 : Closing source stream
DEBUG [FTPClient] 13 Feb 2011 19:06:46.875 : Transferred 9304250 bytes to remote host

I am using version 2.2.1 of edtFTPnet. Capturing network traffic with Wireshark also indicates the same behavior above and proper behavior using FileZilla.

Do you have any ideas or suggestions?

Thanks,

Jim

Answer 1

Enable Filezilla logging and post the log - it should tell us what the difference is.

Answer 2

I'm attaching a FileZilla log. The strange thing is I'm seeing connection time outs but wasn't earlier. Still, hoping there is something useful in the log. I was going to post the log but didn't see a way to do this. I guess I don't use forums enough. :) So, sorry for all the text.

Jim

2011-02-13 20:02:56 4268 2 Status: Connecting to 69.2.205.51:21...
2011-02-13 20:02:56 4268 2 Status: Connection established, waiting for welcome message...
2011-02-13 20:02:56 4268 2 Response: 220-Microsoft FTP Service
2011-02-13 20:02:56 4268 2 Response: 220 ReunionDB FTP Site
2011-02-13 20:02:56 4268 2 Command: USER svc_gr
2011-02-13 20:02:56 4268 2 Response: 331 Password required for svc_gr.
2011-02-13 20:02:56 4268 2 Command: PASS ******
2011-02-13 20:02:56 4268 2 Response: 230-Welcome to ReunionDB FTP Site
2011-02-13 20:02:57 4268 2 Response: 230 User svc_gr logged in.
2011-02-13 20:02:57 4268 2 Command: SYST
2011-02-13 20:02:57 4268 2 Response: 215 Windows_NT
2011-02-13 20:02:57 4268 2 Command: FEAT
2011-02-13 20:02:57 4268 2 Response: 211-FEAT
2011-02-13 20:02:57 4268 2 Response: SIZE
2011-02-13 20:02:57 4268 2 Response: MDTM
2011-02-13 20:02:57 4268 2 Response: 211 END
2011-02-13 20:02:57 4268 2 Status: Connected
2011-02-13 20:02:57 4268 2 Status: Retrieving directory listing...
2011-02-13 20:02:57 4268 2 Command: PWD
2011-02-13 20:02:57 4268 2 Response: 257 "/" is current directory.
2011-02-13 20:02:57 4268 2 Command: TYPE I
2011-02-13 20:02:57 4268 2 Response: 200 Type set to I.
2011-02-13 20:02:57 4268 2 Command: PASV
2011-02-13 20:02:57 4268 2 Response: 227 Entering Passive Mode (69,2,205,51,19,144).
2011-02-13 20:02:57 4268 2 Command: LIST
2011-02-13 20:02:58 4268 2 Response: 125 Data connection already open; Transfer starting.
2011-02-13 20:02:58 4268 2 Response: 226 Transfer complete.
2011-02-13 20:02:58 4268 2 Status: Directory listing successful
2011-02-13 20:03:00 4268 2 Status: Retrieving directory listing...
2011-02-13 20:03:00 4268 2 Command: CWD gr
2011-02-13 20:03:00 4268 2 Response: 250 CWD command successful.
2011-02-13 20:03:00 4268 2 Command: PWD
2011-02-13 20:03:00 4268 2 Response: 257 "/gr" is current directory.
2011-02-13 20:03:00 4268 2 Command: PASV
2011-02-13 20:03:00 4268 2 Response: 227 Entering Passive Mode (69,2,205,51,19,145).
2011-02-13 20:03:00 4268 2 Command: LIST
2011-02-13 20:03:01 4268 2 Response: 125 Data connection already open; Transfer starting.
2011-02-13 20:03:01 4268 2 Response: 226 Transfer complete.
2011-02-13 20:03:01 4268 2 Status: Directory listing successful
2011-02-13 20:03:02 4268 2 Status: Retrieving directory listing...
2011-02-13 20:03:02 4268 2 Command: CWD test
2011-02-13 20:03:02 4268 2 Response: 250 CWD command successful.
2011-02-13 20:03:02 4268 2 Command: PWD
2011-02-13 20:03:02 4268 2 Response: 257 "/gr/test" is current directory.
2011-02-13 20:03:02 4268 2 Command: PASV
2011-02-13 20:03:02 4268 2 Response: 227 Entering Passive Mode (69,2,205,51,19,146).
2011-02-13 20:03:02 4268 2 Command: LIST
2011-02-13 20:03:03 4268 2 Response: 125 Data connection already open; Transfer starting.
2011-02-13 20:03:03 4268 2 Response: 226 Transfer complete.
2011-02-13 20:03:03 4268 2 Status: Directory listing successful
2011-02-13 20:03:06 4268 0 Status: Connecting to 69.2.205.51:21...
2011-02-13 20:03:06 4268 0 Status: Connection established, waiting for welcome message...
2011-02-13 20:03:06 4268 0 Response: 220-Microsoft FTP Service
2011-02-13 20:03:07 4268 0 Response: 220 ReunionDB FTP Site
2011-02-13 20:03:07 4268 0 Command: USER svc_gr
2011-02-13 20:03:07 4268 0 Response: 331 Password required for svc_gr.
2011-02-13 20:03:07 4268 0 Command: PASS ******
2011-02-13 20:03:07 4268 0 Response: 230-Welcome to ReunionDB FTP Site
2011-02-13 20:03:07 4268 0 Response: 230 User svc_gr logged in.
2011-02-13 20:03:07 4268 0 Status: Connected
2011-02-13 20:03:07 4268 0 Status: Starting upload of C:\Temp\GRI Data\DIY Files\test.7z
2011-02-13 20:03:07 4268 0 Command: CWD /gr/test
2011-02-13 20:03:07 4268 0 Response: 250 CWD command successful.
2011-02-13 20:03:07 4268 0 Command: PWD
2011-02-13 20:03:07 4268 0 Response: 257 "/gr/test" is current directory.
2011-02-13 20:03:07 4268 0 Command: TYPE I
2011-02-13 20:03:07 4268 0 Response: 200 Type set to I.
2011-02-13 20:03:07 4268 0 Command: PASV
2011-02-13 20:03:07 4268 0 Response: 227 Entering Passive Mode (69,2,205,51,19,147).
2011-02-13 20:03:07 4268 0 Command: STOR test.7z
2011-02-13 20:03:07 4268 0 Response: 125 Data connection already open; Transfer starting.
2011-02-13 20:04:39 4268 0 Error: Connection timed out
2011-02-13 20:04:39 4268 0 Error: File transfer failed after transferring 9,304,250 bytes in 92 seconds
2011-02-13 20:04:39 4268 0 Status: Connecting to 69.2.205.51:21...
2011-02-13 20:04:39 4268 0 Status: Connection established, waiting for welcome message...
2011-02-13 20:04:39 4268 0 Response: 220-Microsoft FTP Service
2011-02-13 20:04:39 4268 0 Response: 220 ReunionDB FTP Site
2011-02-13 20:04:39 4268 0 Command: USER svc_gr
2011-02-13 20:04:39 4268 0 Response: 331 Password required for svc_gr.
2011-02-13 20:04:39 4268 0 Command: PASS ******
2011-02-13 20:04:40 4268 0 Response: 230-Welcome to ReunionDB FTP Site
2011-02-13 20:04:40 4268 0 Response: 230 User svc_gr logged in.
2011-02-13 20:04:40 4268 0 Status: Connected
2011-02-13 20:04:40 4268 0 Status: Starting upload of C:\Temp\GRI Data\DIY Files\test.7z
2011-02-13 20:04:40 4268 0 Command: CWD /gr/test
2011-02-13 20:04:40 4268 0 Response: 250 CWD command successful.
2011-02-13 20:04:40 4268 0 Status: Retrieving directory listing...
2011-02-13 20:04:40 4268 0 Command: TYPE I
2011-02-13 20:04:40 4268 0 Response: 200 Type set to I.
2011-02-13 20:04:40 4268 0 Command: PASV
2011-02-13 20:04:40 4268 0 Response: 227 Entering Passive Mode (69,2,205,51,19,140).
2011-02-13 20:04:40 4268 0 Command: LIST
2011-02-13 20:04:40 4268 0 Response: 125 Data connection already open; Transfer starting.
2011-02-13 20:04:40 4268 0 Response: 226 Transfer complete.
2011-02-13 20:04:40 4268 0 Command: PASV
2011-02-13 20:04:41 4268 0 Response: 227 Entering Passive Mode (69,2,205,51,19,148).
2011-02-13 20:04:41 4268 0 Command: APPE test.7z
2011-02-13 20:04:41 4268 0 Response: 125 Data connection already open; Transfer starting.
2011-02-13 20:04:41 4268 0 Response: 226 Transfer complete.
2011-02-13 20:04:41 4268 0 Status: File transfer successful, transferred 0 bytes in 1 second
2011-02-13 20:04:41 4268 0 Status: Retrieving directory listing...
2011-02-13 20:04:41 4268 0 Command: PASV
2011-02-13 20:04:41 4268 0 Response: 227 Entering Passive Mode (69,2,205,51,19,149).
2011-02-13 20:04:41 4268 0 Command: LIST
2011-02-13 20:04:41 4268 0 Response: 125 Data connection already open; Transfer starting.
2011-02-13 20:04:42 4268 0 Response: 226 Transfer complete.
2011-02-13 20:04:42 4268 0 Status: Directory listing successful
2011-02-13 20:05:02 4268 2 Status: Disconnected from server

Answer 3

It looks like FZ does the same thing and then resumes the transfer. Perhaps the server is timing out the transfer on its end?

Answer 4

Bruce,

Thanks for looking at this. I'm including a cleaner log file from FileZilla - no connection timeouts. As I mentioned, I don't understand why FileZilla gets the 226 reply but when I only get this reply when I send small files using edtFTPnet.

2011-02-14 18:08:22 1828 2 Status: Connecting to 69.2.205.51:21...
2011-02-14 18:08:22 1828 2 Status: Connection established, waiting for welcome message...
2011-02-14 18:08:22 1828 2 Response: 220-Microsoft FTP Service
2011-02-14 18:08:23 1828 2 Response: 220 ReunionDB FTP Site
2011-02-14 18:08:23 1828 2 Command: USER svc_gr
2011-02-14 18:08:23 1828 2 Response: 331 Password required for svc_gr.
2011-02-14 18:08:23 1828 2 Command: PASS ******
2011-02-14 18:08:23 1828 2 Response: 230-Welcome to ReunionDB FTP Site
2011-02-14 18:08:23 1828 2 Response: 230 User svc_gr logged in.
2011-02-14 18:08:23 1828 2 Command: SYST
2011-02-14 18:08:23 1828 2 Response: 215 Windows_NT
2011-02-14 18:08:23 1828 2 Command: FEAT
2011-02-14 18:08:23 1828 2 Response: 211-FEAT
2011-02-14 18:08:23 1828 2 Response: SIZE
2011-02-14 18:08:23 1828 2 Response: MDTM
2011-02-14 18:08:23 1828 2 Response: 211 END
2011-02-14 18:08:23 1828 2 Status: Connected
2011-02-14 18:08:23 1828 2 Status: Retrieving directory listing...
2011-02-14 18:08:23 1828 2 Command: PWD
2011-02-14 18:08:23 1828 2 Response: 257 "/" is current directory.
2011-02-14 18:08:23 1828 2 Command: TYPE I
2011-02-14 18:08:24 1828 2 Response: 200 Type set to I.
2011-02-14 18:08:24 1828 2 Command: PASV
2011-02-14 18:08:24 1828 2 Response: 227 Entering Passive Mode (69,2,205,51,19,137).
2011-02-14 18:08:24 1828 2 Command: LIST
2011-02-14 18:08:24 1828 2 Response: 125 Data connection already open; Transfer starting.
2011-02-14 18:08:24 1828 2 Response: 226 Transfer complete.
2011-02-14 18:08:24 1828 2 Status: Directory listing successful
2011-02-14 18:08:27 1828 2 Status: Retrieving directory listing...
2011-02-14 18:08:27 1828 2 Command: CWD gr
2011-02-14 18:08:27 1828 2 Response: 250 CWD command successful.
2011-02-14 18:08:27 1828 2 Command: PWD
2011-02-14 18:08:27 1828 2 Response: 257 "/gr" is current directory.
2011-02-14 18:08:27 1828 2 Command: PASV
2011-02-14 18:08:27 1828 2 Response: 227 Entering Passive Mode (69,2,205,51,19,138).
2011-02-14 18:08:27 1828 2 Command: LIST
2011-02-14 18:08:28 1828 2 Response: 125 Data connection already open; Transfer starting.
2011-02-14 18:08:28 1828 2 Response: 226 Transfer complete.
2011-02-14 18:08:28 1828 2 Status: Directory listing successful
2011-02-14 18:08:29 1828 2 Status: Retrieving directory listing...
2011-02-14 18:08:29 1828 2 Command: CWD test
2011-02-14 18:08:29 1828 2 Response: 250 CWD command successful.
2011-02-14 18:08:29 1828 2 Command: PWD
2011-02-14 18:08:29 1828 2 Response: 257 "/gr/test" is current directory.
2011-02-14 18:08:29 1828 2 Command: PASV
2011-02-14 18:08:29 1828 2 Response: 227 Entering Passive Mode (69,2,205,51,19,139).
2011-02-14 18:08:29 1828 2 Command: LIST
2011-02-14 18:08:30 1828 2 Response: 125 Data connection already open; Transfer starting.
2011-02-14 18:08:30 1828 2 Response: 226 Transfer complete.
2011-02-14 18:08:30 1828 2 Status: Directory listing successful
2011-02-14 18:08:37 1828 2 Command: DELE test.7z
2011-02-14 18:08:38 1828 2 Response: 250 DELE command successful.
2011-02-14 18:08:43 1828 0 Status: Connecting to 69.2.205.51:21...
2011-02-14 18:08:43 1828 0 Status: Connection established, waiting for welcome message...
2011-02-14 18:08:43 1828 0 Response: 220-Microsoft FTP Service
2011-02-14 18:08:43 1828 0 Response: 220 ReunionDB FTP Site
2011-02-14 18:08:43 1828 0 Command: USER svc_gr
2011-02-14 18:08:43 1828 0 Response: 331 Password required for svc_gr.
2011-02-14 18:08:43 1828 0 Command: PASS ******
2011-02-14 18:08:43 1828 0 Response: 230-Welcome to ReunionDB FTP Site
2011-02-14 18:08:44 1828 0 Response: 230 User svc_gr logged in.
2011-02-14 18:08:44 1828 0 Status: Connected
2011-02-14 18:08:44 1828 0 Status: Starting upload of C:\Temp\GRI Data\DIY Files\test.7z
2011-02-14 18:08:44 1828 0 Command: CWD /gr/test
2011-02-14 18:08:44 1828 0 Response: 250 CWD command successful.
2011-02-14 18:08:44 1828 0 Command: PWD
2011-02-14 18:08:44 1828 0 Response: 257 "/gr/test" is current directory.
2011-02-14 18:08:44 1828 0 Command: TYPE I
2011-02-14 18:08:44 1828 0 Response: 200 Type set to I.
2011-02-14 18:08:44 1828 0 Command: PASV
2011-02-14 18:08:44 1828 0 Response: 227 Entering Passive Mode (69,2,205,51,19,140).
2011-02-14 18:08:44 1828 0 Command: STOR test.7z
2011-02-14 18:08:44 1828 0 Response: 125 Data connection already open; Transfer starting.
2011-02-14 18:09:49 1828 0 Response: 226 Transfer complete.
2011-02-14 18:09:49 1828 0 Status: File transfer successful, transferred 9,304,250 bytes in 65 seconds
2011-02-14 18:09:49 1828 0 Status: Retrieving directory listing...
2011-02-14 18:09:49 1828 0 Command: PASV
2011-02-14 18:09:49 1828 0 Response: 227 Entering Passive Mode (69,2,205,51,19,141).
2011-02-14 18:09:49 1828 0 Command: LIST
2011-02-14 18:09:49 1828 0 Response: 125 Data connection already open; Transfer starting.
2011-02-14 18:09:50 1828 0 Response: 226 Transfer complete.
2011-02-14 18:09:50 1828 0 Status: Directory listing successful
2011-02-14 18:10:03 1828 2 Status: Disconnected from server


Thanks,

Jim

Answer 5

It looks to me as though the server times out the connection if the transfer takes longer than 90 seconds, irrespective of the client.

Try some slightly smaller (but still large) files with edtFTPnet to verify that theory.