Our Products:   CompleteFTP  edtFTPnet/Free  edtFTPnet/PRO  edtFTPj/Free  edtFTPj/PRO
0 votes
6.3k views
in .NET FTP by (500 points)
I am seeing some interesting behavior when trying to connect to my FTP server. Most of the time, the connection is successful but there are times when it fails and the log file gives no indication as to why it is failing. For instance, here's the log file entries of interest (I'm including the failure [in dark red] followed by a successful transfer):

DEBUG [FTPConnection] 9 May 2011 16:42:44.218 : Set LocalDirectory='C:\Program Files (x86)\FetalConnect\bin'
DEBUG [FTPClient] 9 May 2011 16:42:44.218 : Connecting to 66.96.147.103:21
DEBUG [HostNameResolver] 9 May 2011 16:42:44.218 : Resolving 66.96.147.103
DEBUG [HostNameResolver] 9 May 2011 16:42:44.218 : 66.96.147.103 resolved to 66.96.147.103
INFO [BaseSocket] 9 May 2011 16:42:44.218 : Connecting to 66.96.147.103:21 with timeout 30000 ms
DEBUG [FTPControlSocket] 9 May 2011 16:42:44.218 : Setting socket timeout=30000
DEBUG [FTPConnection] 9 May 2011 16:43:05.590 : Set LocalDirectory='C:\Program Files (x86)\FetalConnect\bin'
DEBUG [FTPClient] 9 May 2011 16:43:05.590 : Connecting to 66.96.147.103:21
DEBUG [HostNameResolver] 9 May 2011 16:43:05.590 : Resolving 66.96.147.103
DEBUG [HostNameResolver] 9 May 2011 16:43:05.590 : 66.96.147.103 resolved to 66.96.147.103
INFO [BaseSocket] 9 May 2011 16:43:05.590 : Connecting to 66.96.147.103:21 with timeout 30000 ms
DEBUG [FTPControlSocket] 9 May 2011 16:43:05.793 : Setting socket timeout=30000
INFO [FTPControlSocket] 9 May 2011 16:43:05.793 : Command encoding=System.Text.SBCSCodePageEncoding
DEBUG [FTPControlSocket] 9 May 2011 16:43:05.793 : StrictReturnCodes=False
DEBUG [FTPControlSocket] 9 May 2011 16:43:06.105 : 220-
DEBUG [FTPControlSocket] 9 May 2011 16:43:06.791 : 220 Ipage FTP Server ready
DEBUG [FTPConnection] 9 May 2011 16:43:06.791 : Connected to 66.96.147.103 (instance=10)
DEBUG [FTPControlSocket] 9 May 2011 16:43:06.791 : ---> USER test
DEBUG [FTPControlSocket] 9 May 2011 16:43:06.900 : 331 Password required for test
DEBUG [FTPControlSocket] 9 May 2011 16:43:06.900 : ---> PASS ********
DEBUG [FTPControlSocket] 9 May 2011 16:43:07.072 : 230 User test logged in
DEBUG [FTPConnection] 9 May 2011 16:43:07.072 : Successfully logged in
DEBUG [FTPControlSocket] 9 May 2011 16:43:07.072 : ---> FEAT
DEBUG [FTPControlSocket] 9 May 2011 16:43:07.197 : 211-Features:
DEBUG [FTPControlSocket] 9 May 2011 16:43:07.197 : MDTM
DEBUG [FTPControlSocket] 9 May 2011 16:43:07.197 : MFMT
DEBUG [FTPControlSocket] 9 May 2011 16:43:07.197 : TVFS
DEBUG [FTPControlSocket] 9 May 2011 16:43:07.197 : MFF modify;UNIX.group;UNIX.mode;
DEBUG [FTPControlSocket] 9 May 2011 16:43:07.197 : MLST modify*;perm*;size*;type*;unique*;UNIX.group*;UNIX.mode*;UNIX.owner*;
DEBUG [FTPControlSocket] 9 May 2011 16:43:07.197 : SITE MKDIR
DEBUG [FTPControlSocket] 9 May 2011 16:43:07.197 : SITE RMDIR
DEBUG [FTPControlSocket] 9 May 2011 16:43:07.197 : SITE UTIME
DEBUG [FTPControlSocket] 9 May 2011 16:43:07.197 : SITE SYMLINK
DEBUG [FTPControlSocket] 9 May 2011 16:43:07.197 : REST STREAM
DEBUG [FTPControlSocket] 9 May 2011 16:43:07.197 : SIZE
DEBUG [FTPControlSocket] 9 May 2011 16:43:07.509 : 211 End
DEBUG [FTPControlSocket] 9 May 2011 16:43:07.509 : ---> TYPE I
DEBUG [FTPControlSocket] 9 May 2011 16:43:07.633 : 200 Type set to I
DEBUG [FTPControlSocket] 9 May 2011 16:43:07.633 : ---> PWD
DEBUG [FTPControlSocket] 9 May 2011 16:43:07.743 : 257 "/" is the current directory
DEBUG [FTPControlSocket] 9 May 2011 16:43:07.743 : NewActiveDataSocket(0)
DEBUG [FTPControlSocket] 9 May 2011 16:43:07.743 : ---> PORT 192,168,11,107,194,191
DEBUG [FTPControlSocket] 9 May 2011 16:43:08.055 : 200 PORT command successful
DEBUG [FTPControlSocket] 9 May 2011 16:43:08.055 : ---> STOR C:\Data\GSH008.zip
DEBUG [FTPControlSocket] 9 May 2011 16:43:08.320 : 150 Opening BINARY mode data connection for C:\Data\GSH008.zip
DEBUG [FTPActiveDataSocket] 9 May 2011 16:43:08.320 : AcceptConnection() succeeded
DEBUG [FTPClient] 9 May 2011 16:43:08.320 : Closing source stream
DEBUG [FTPClient] 9 May 2011 16:43:08.320 : Transferred 44072 bytes to remote host
DEBUG [FTPControlSocket] 9 May 2011 16:43:08.788 : 226 Transfer complete
DEBUG [FTPConnection] 9 May 2011 16:43:08.788 : GetLastWriteTime(C:\Data\GSH008.zip)
DEBUG [FTPControlSocket] 9 May 2011 16:43:08.788 : ---> MDTM C:\Data\GSH008.zip
DEBUG [FTPControlSocket] 9 May 2011 16:43:08.897 : 213 20110509234307
DEBUG [FTPConnection] 9 May 2011 16:43:08.897 : Closing connection (instance=10)
DEBUG [FTPFileFactory] 9 May 2011 16:43:08.897 : Defaulting to Unix parsing
DEBUG [FTPControlSocket] 9 May 2011 16:43:08.897 : ---> QUIT
DEBUG [FTPControlSocket] 9 May 2011 16:43:09.022 : 221 Goodbye.

As you can see, there is no error, warning or exception being thrown at least that gets recorded into the log file. Does anyone have any idea what might be causing this behavior? Do I need to include the code as well or can we figure it out from the log entries?

Any help is appreciated on resolving this problem.

8 Answers

0 votes
by (162k points)
Sorry for the late reply. Any success with this? The log doesn't really help much. Can it be replicated in a debugger?
0 votes
by (500 points)
Sorry for the delay in responding. I deployed this solution at our customer site yesterday and it did this every time it ran. It never successfully connected to the FTP server. Since the customer site is a hospital, I can't really do much debugging in that setting.

But, I can run in the debugger here at home (my work location). Unfortunately, it rarely happens here although it does happen every once in a while. So I am very open to running this in the debugger if there are things that can be done to help determine the problem and the solution.

Is it possible that something in the network (firewall configuration perhaps) is causing this problem? Could it be that FTP service is blocked by the customer's firewall settings? Is there something else that could account for this? Given the lack of information in the log, this is a very difficult problem to understand. I'm just not sure what is going on but I do have to get it resolved quickly as I only have until Monday to fix the problem. I may have to try a different FTP solution if this one is not going to work although I'm not sure another FTP library (or doing it directly through Windows) is really going to work any better since I don't know what is causing the problem.
0 votes
by (500 points)
By the way, here is the code I am using. This is a WPF application so I have implemented it as a backgroundworker task. Here are the pertinent methods that I am using:
      void SendClick(object sender, RoutedEventArgs e)
      {
         // create a background worker thread and set its parameters
         bgWorker = new BackgroundWorker();
         bgWorker.WorkerReportsProgress = true;
         bgWorker.WorkerSupportsCancellation = false;
         bgWorker.DoWork += DoWork;
         bgWorker.ProgressChanged += ProgressChanged;
         bgWorker.RunWorkerCompleted += WorkerComplete;
         
         SetStatus("Transferring data to the server...");
         
         // start the background worker thread
         bgWorker.RunWorkerAsync();
      }
      
      private void DoWork(object sender, DoWorkEventArgs e)
      {
         FTPConnection      ftp;
         string            zipFile;
         FileStream         stream;
         BackgroundWorker   worker = sender as BackgroundWorker;
         bool            uploadSucceded;
         
         xferStatus = true;
         ftp = new FTPConnection();
         ftp.LocalDirectory = DIRECTORY;
         // set log information
         FTPConnection.LogFile = string.Format("ftp.log");
         FTPConnection.LogLevel = LogLevel.All;
         // set all of the FTP parameters
         ftp.ServerAddress = "66.96.147.103";
         // this is not the real login name and password...
         ftp.UserName = "xxxx";
         ftp.Password = "help me";
         ftp.ConnectMode = FTPConnectMode.ACTIVE;
         ftp.TransferType = FTPTransferType.BINARY;
         ftp.AutoLogin = true;
         ftp.Timeout = 30000;
         ftp.UseGuiThreadIfAvailable = false;
         // connect to the server
         ftp.Connect();
         if (ftp.IsConnected) {
//            ftp.Uploaded += new FTPFileTransferEventHandler(FileUploadComplete);
            for (int i = (numberPatients - 1); i >= 0; i--) {
               zipFile = string.Format("{0}.zip", patients[i]);
               worker.ReportProgress(0, string.Format("Transferring file {0}", zipFile));
               stream = File.OpenRead(zipFile);
               stream.Seek(0, SeekOrigin.Begin);
               try {
                  uploadSucceded = true;
                  ftp.UploadStream(stream, zipFile);
               } catch (Exception) {
                  // if we have an exception, then the upload failed
                  uploadSucceded = false;
               }
               if (uploadSucceded) {
                  // the upload was successful so delete the files
                  File.Delete(zipFile);
                  // clear the patient from the list & interface
                  patients[i] = string.Empty;
                  numberPatients--;
                  worker.ReportProgress(1);
//                  DisplayPatients();
               } else {
                  xferStatus = false;
               }
            }
         }
         ftp.Close();
      }
      
      private void ProgressChanged(object sender, ProgressChangedEventArgs e)
      {
         switch (e.ProgressPercentage) {
            case 0:   // update status message
               SetStatus((string)e.UserState);
               break;
            case 1:   // update patient display
               DisplayPatients();
               break;
            default:
               // do nothing in this case
               break;
         }
      }
      
      private void WorkerComplete(object sender, RunWorkerCompletedEventArgs e)
      {
         SetStatus(string.Format("File transfer completed {0}. Ready.",
                                 xferStatus?"successfully":"unsuccessfully"));
         UpdateControls();
         UpdateDiskSpace();
         DisplayPatients();
 
0 votes
by (162k points)
You need at least a try/catch (and print) around the code in DoWork - any exceptions thrown there aren't being recorded. That will tell you what the problem is.

It is likely that a firewall is preventing the connection. Try ftp.exe or Filezilla to confirm.
0 votes
by (500 points)
Where do you suggest the additional try/catch pairs? I have to one around the UploadStream() call which should catch anything there. Should I include one around the Connect() call as well? That seems to be where the problem is so that would probably be a good idea regardless. The only other call is to Close() but that doesn't seem like it would need a try/catch pair. Do you have any example code that demonstrates what you would typically do?

I will have to check with the hospital IT guys once I get back to the site. I'm not sure if they can punch a hole in the firewall for me or not. I could try setting my router here to deny FTP and see if that replicates the problem.
0 votes
by (162k points)
Yes, Connect() and Close() should be included in the try/catch.
0 votes
by (500 points)
OK, I've put try/catch around all of the FTP calls. It turns out that the main problem was that the user has to go through a "welcome" screen prior to being allowed to do an FTP transfer. I've updated my instructions to them to do that step first and then the transfer should succeed.
0 votes
by (162k points)
Thanks for following up with the solution.

Categories

...