edtFTPnet - Error after file downloads

Question

Hello,

I'm downloading a large (30MB) file via a proxy. The proxy does not send any data to my client until it has received all of the file from the remote server. When I download the file the first time the ftp client often gives the following error:

2007-07-13 14:43:49,435 [3580] EnterpriseDT.Net.Ftp.FTPException: The FTP client has not yet connected to the server.  The requested action cannot be performed until after a connection has been established.
   at EnterpriseDT.Net.Ftp.FTPClient.CheckConnection(Boolean shouldBeConnected)
   at EnterpriseDT.Net.Ftp.FTPClient.ValidateTransferOnError()
   at EnterpriseDT.Net.Ftp.FTPClient.Get(String localPath, String remoteFile)

The corresponding log from the edtFTPNet log file is:

DEBUG [FTPControlSocket] 13 Jul 2007 14:28:45.384 : ---> TYPE I
DEBUG [FTPControlSocket] 13 Jul 2007 14:28:45.463 : 200 Type set to IMAGE.
DEBUG [FTPControlSocket] 13 Jul 2007 14:28:45.463 : ---> PASV
DEBUG [FTPControlSocket] 13 Jul 2007 14:28:45.463 : 227 Entering Passive Mode (10,81,39,2,134,153)
DEBUG [FTPControlSocket] 13 Jul 2007 14:28:45.463 : Server supplied address=10.81.39.2
DEBUG [FTPControlSocket] 13 Jul 2007 14:28:45.463 : Server supplied port=34457
DEBUG [FTPControlSocket] 13 Jul 2007 14:28:45.463 : NewPassiveDataSocket(10.81.39.2,34457)
DEBUG [FTPControlSocket] 13 Jul 2007 14:28:45.463 : ---> RETR /V2.5/IVYDB.20070705D.zip
DEBUG [FTPControlSocket] 13 Jul 2007 14:28:46.744 : 150 Opening BINARY data connection for \V2.5\IVYDB.20070705D.zip (30088422 bytes)
DEBUG [FTPClient] 13 Jul 2007 14:43:49.435 : Transferred 30088422 bytes from remote host

The file itself downloads fine - despite the error. If I then download the file again (when it is then cached by our proxy, so downloads in a much shorter time) I get no error. I have set the Timeout property on the FTPClient, but wonder if I need to set it somewhere else as well?

Thanks in advance for any help.

Answer 1

What timeout are you setting?

Answer 2

I've set the Timeout to 30 minutes:

ftp.Timeout = 1000 * 60 * 30;

I also have put a wakeup interval of 1 minute, but this didn't make a difference to this problem:

ftp.ServerWakeupInterval = 1;

Answer 3

Can you post more of the log? We'd like to see how that FTPException arises.

Answer 4

Sure, thanks for the help - the full exception is:

2007-07-16 10:28:31,778 [2632] FATAL barcap.research.ed.batch.FolderCopy - EnterpriseDT.Net.Ftp.FTPException: The FTP client has not yet connected to the server.  The requested action cannot be performed until after a connection has been established.
   at EnterpriseDT.Net.Ftp.FTPClient.CheckConnection(Boolean shouldBeConnected) in z:\bo_research_it\equityderivatives\batch\edtftpnet-1.2.5\src\net\ftp\ftpclient.cs:line 1337
   at EnterpriseDT.Net.Ftp.FTPClient.ValidateTransferOnError() in z:\bo_research_it\equityderivatives\batch\edtftpnet-1.2.5\src\net\ftp\ftpclient.cs:line 1696
   at EnterpriseDT.Net.Ftp.FTPClient.Get(String localPath, String remoteFile) in z:\bo_research_it\equityderivatives\batch\edtftpnet-1.2.5\src\net\ftp\ftpclient.cs:line 2130
   at barcap.research.ed.batch.FolderCopy.Main(String[] args) in z:\bo_research_it\equityderivatives\batch\foldercopyftp\foldercopy.cs:line 135

(I have just recompiled in Debug with version 1.2.5)

The appropriate part of the FTP log is:

DEBUG [FTPControlSocket] 16 Jul 2007 10:14:44.017 : 227 Entering Passive Mode (10,81,39,2,212,231)
DEBUG [FTPControlSocket] 16 Jul 2007 10:14:44.017 : Server supplied address=10.81.39.2
DEBUG [FTPControlSocket] 16 Jul 2007 10:14:44.017 : Server supplied port=54503
DEBUG [FTPControlSocket] 16 Jul 2007 10:14:44.017 : NewPassiveDataSocket(10.81.39.2,54503)
DEBUG [FTPControlSocket] 16 Jul 2007 10:14:44.017 : ---> NLST /V2.5/IVYDB.20070620D.zip
DEBUG [FTPControlSocket] 16 Jul 2007 10:14:44.502 : 150 Opening ASCII data connection for directory listing
DEBUG [FTPClient] 16 Jul 2007 10:14:44.517 : Reading ASCII listing data
DEBUG [FTPClient] 16 Jul 2007 10:14:44.611 : -->IVYDB.20070620D.zip
DEBUG [FTPControlSocket] 16 Jul 2007 10:14:44.627 : 226 transfer complete
DEBUG [FTPClient] 16 Jul 2007 10:14:44.627 : Found 1 listing lines
DEBUG [FTPControlSocket] 16 Jul 2007 10:14:44.627 : ---> TYPE I
DEBUG [FTPControlSocket] 16 Jul 2007 10:14:44.721 : 200 Type set to IMAGE.
DEBUG [FTPControlSocket] 16 Jul 2007 10:14:45.533 : ---> PASV
DEBUG [FTPControlSocket] 16 Jul 2007 10:14:45.533 : 227 Entering Passive Mode (10,81,39,2,69,178)
DEBUG [FTPControlSocket] 16 Jul 2007 10:14:45.533 : Server supplied address=10.81.39.2
DEBUG [FTPControlSocket] 16 Jul 2007 10:14:45.533 : Server supplied port=17842
DEBUG [FTPControlSocket] 16 Jul 2007 10:14:45.533 : NewPassiveDataSocket(10.81.39.2,17842)
DEBUG [FTPControlSocket] 16 Jul 2007 10:14:45.533 : ---> RETR /V2.5/IVYDB.20070620D.zip
DEBUG [FTPControlSocket] 16 Jul 2007 10:14:46.877 : 150 Opening BINARY data connection for \V2.5\IVYDB.20070620D.zip (29824780 bytes)
DEBUG [FTPClient] 16 Jul 2007 10:28:15.418 : Transferred 29824780 bytes from remote host

On this last failure I stepped though the code and it appeared to happen on like 1677, in the ValidateTransfer function:

            // check the control response
            FTPReply reply = control.ReadReply();

Answer 5

Is there more of the log around the exception?

It seems to be thrown at 10:28:31,778, while the last line of the log is:

DEBUG [FTPClient] 16 Jul 2007 10:28:15.418

I'd also expect the stack trace to be shown in the log (?).

Answer 6

That is all there is in the FTPClient's own log, setup using:

         EnterpriseDT.Util.Debug.Logger.CurrentLevel = EnterpriseDT.Util.Debug.Level.ALL;
         
         EnterpriseDT.Util.Debug.Logger.AddAppender( new EnterpriseDT.Util.Debug.FileAppender("C:\\ftp.txt"));

The exception is printed by the logging in my program - which doesn't have more than I posted earlier. From stepping through it looks like the download completes, then in the ValidateTransfer() function the call the get the FTP server's reply code fails, which then throws an error, and then during the call to ValidateTransferOnError the connection check then thinks that it is disconnected.

Is there a "correct" point to set the timeout - for example, do I have to do it before or after connection?

Thanks.

Answer 7

It looks to me like the control connection is timing out.

You need to set the timeout *before* connecting - otherwise it won't apply to the control connection.

Answer 8

I had been setting it after the connection, however I moved the code to be :

               FTPClient ftp = new FTPClient();
               ftp.Timeout = 1000 * 60 * 30; // Allow 30 minutes to get a file...

But it still failed in the same manner. I've tried with both active and passive (the default I believe), and get the same error with either.

Thanks for the help, much appreciated! I wondered that if the proxy is returning all the dats at the end, would I need to enable multi threading so that the control connection can be kept alive during the file transfer?

Answer 9

Sorry, we're running out of ideas. Perhaps the proxy is closing the connection? What happens with other FTP clients?

Answer 10

I've not used another FTP API - but using either the Windows ftp utility, or "Easy FTP Pro" I don't get any errors reported.

I agree with your suggestion that the proxy must be closign the connection. Looking at the code it seems to me that when looping to read data if I set the ServerWakeUpInterval property the No op never gets sent, because the first read doesn't get any data back until the proxy has cached the whole file.

Do you think it is worth me changing my program to have a separate thread that gets a no op sent during transfer?

thanks again.