put() hangs

Question

I am using the following code:

if( ! asciiType ) 
            m_client.setType( FTPTransferType.BINARY );
        else
            m_client.setType( FTPTransferType.ASCII );
        
        
        if(usePassive)
            m_client.setConnectMode( FTPConnectMode.PASV );
        else
            m_client.setConnectMode( FTPConnectMode.ACTIVE);
        
        m_client.put( file.getCanonicalPath(), remoteName );

Everything seems to work fine until I tried connecting to an FTP server over the internet. I can retrieve and put files on the server for a while, then suddenly it just hangs. It is not the local file as it happens on different files. I cannot seem to find any consistancy.

The server throws a 553 data transfer failed error, yet the client still sits there.

I have a timeout of 15000 on the socket, and it doesnt timeout either. I left it running for 5 minutes without a timeout exception.

This is happening on Windows XP running JDK 1.4.2-b28, edtftpj-1.4.5.

Thanks!

Answer 1

Just FYI MaxFTPTimeout must be in milliseconds, e.g. 60000 should be the minimum timeout used (60 s).

Thanks Bruce. I have tried 2 minutes or 3 minutes. But still get timeout exception only after about 10 minutes

is there any other thing that I have missed?

Thanks much....-Steve

Answer 2

I just realized you are running edtftpj-1.4.5. This version is almost 4 years old and there have been many releases since. You should upgrade to the latest version if this is possible (you will need to recompile). At least then we will know where you are coming from, and it might even fix the problem.

Answer 3

I just realized you are running edtftpj-1.4.5.

Hi Bruce. I am using the most recent version.(someone else was using old version, not me) I turned on debug. Here is the log:
(I set timeout as 4 minutes, but it only timeout after about 10 minutes after fiber cut. static private final int MaxFTPTimeout = 240000;)

01 Jul 2008 21:25:43,880 [Chassis Pool] DEBUG - updateSummaryStatus 9/pon2/7 Reply received: 220 Tornado-vxWorks (VxWorks 6.2) FTP server ready false false
01 Jul 2008 21:25:43,880 [Chassis Pool] DEBUG - Unable to find DeviceStatus for 9/pon2/7 Reply received
01 Jul 2008 21:25:43,900 [Chassis Pool] DEBUG - forward notification module.transfer.progress
01 Jul 2008 21:25:43,900 [Chassis Pool] DEBUG - updateSummaryStatus 9/pon2/7 Command sent: ---> USER scoobydoo false false
01 Jul 2008 21:25:43,900 [Chassis Pool] DEBUG - Unable to find DeviceStatus for 9/pon2/7 Command sent
01 Jul 2008 21:25:43,900 [Chassis Pool] DEBUG - forward notification module.transfer.progress
01 Jul 2008 21:25:43,900 [Chassis Pool] DEBUG - updateSummaryStatus 9/pon2/7 Reply received: 331 Password required false false
01 Jul 2008 21:25:43,920 [Chassis Pool] DEBUG - Unable to find DeviceStatus for 9/pon2/7 Reply received
01 Jul 2008 21:25:43,920 [Chassis Pool] DEBUG - forward notification module.transfer.progress
01 Jul 2008 21:25:43,920 [Chassis Pool] DEBUG - updateSummaryStatus 9/pon2/7 Command sent: ---> PASS ******** false false
01 Jul 2008 21:25:43,920 [Chassis Pool] DEBUG - Unable to find DeviceStatus for 9/pon2/7 Command sent
01 Jul 2008 21:25:43,940 [Chassis Pool] DEBUG - forward notification module.transfer.progress
01 Jul 2008 21:25:43,940 [Chassis Pool] DEBUG - updateSummaryStatus 9/pon2/7 Reply received: 230 User logged in false false
01 Jul 2008 21:25:43,940 [Chassis Pool] DEBUG - Unable to find DeviceStatus for 9/pon2/7 Reply received
01 Jul 2008 21:25:43,940 [Chassis Pool] DEBUG - forward notification module.transfer.progress
01 Jul 2008 21:25:43,960 [Chassis Pool] DEBUG - updateSummaryStatus 9/pon2/7 Command sent: ---> TYPE I false false
01 Jul 2008 21:25:43,960 [Chassis Pool] DEBUG - Unable to find DeviceStatus for 9/pon2/7 Command sent
01 Jul 2008 21:25:43,960 [Chassis Pool] DEBUG - forward notification module.transfer.progress
01 Jul 2008 21:25:43,960 [Chassis Pool] DEBUG - updateSummaryStatus 9/pon2/7 Reply received: 200 Type set to I, binary mode false false
01 Jul 2008 21:25:43,960 [Chassis Pool] DEBUG - Unable to find DeviceStatus for 9/pon2/7 Reply received
01 Jul 2008 21:25:43,980 [Chassis Pool] DEBUG - forward notification module.transfer.progress
01 Jul 2008 21:25:43,980 [Chassis Pool] DEBUG - updateSummaryStatus 9/pon2/7: Logging in... false false
01 Jul 2008 21:25:43,980 [Chassis Pool] DEBUG - forward notification module.transfer.progress
01 Jul 2008 21:25:44,000 [Chassis Pool] DEBUG - updateSummaryStatus 9/pon2/7: Starting transfer... false false
01 Jul 2008 21:25:44,000 [Chassis Pool] DEBUG - forward notification module.transfer.progress
01 Jul 2008 21:25:44,000 [Chassis Pool] DEBUG - updateSummaryStatus 9/pon2/7 Command sent: ---> MKD /tffs0/images false false
01 Jul 2008 21:25:44,000 [Chassis Pool] DEBUG - Unable to find DeviceStatus for 9/pon2/7 Command sent
01 Jul 2008 21:25:44,020 [Chassis Pool] DEBUG - forward notification module.transfer.progress
01 Jul 2008 21:25:44,020 [Chassis Pool] DEBUG - updateSummaryStatus 9/pon2/7 Reply received: 550 "/tffs0/images" directory could not be created false false
01 Jul 2008 21:25:44,020 [Chassis Pool] DEBUG - Unable to find DeviceStatus for 9/pon2/7 Reply received
01 Jul 2008 21:25:44,020 [Chassis Pool] ERROR - Unable to create directory: /tffs0/images com.enterprisedt.com.ftp.FTPException: "/tffs0/images" directory could not be created
01 Jul 2008 21:25:44,040 [Chassis Pool] DEBUG - forward notification module.transfer.progress
01 Jul 2008 21:25:44,040 [Chassis Pool] DEBUG - updateSummaryStatus 9/pon2/7 Command sent: ---> DELE /tffs0/images/onte_test.imz.w7 false false
01 Jul 2008 21:25:44,040 [Chassis Pool] DEBUG - Unable to find DeviceStatus for 9/pon2/7 Command sent
01 Jul 2008 21:25:44,060 [Chassis Pool] DEBUG - forward notification module.transfer.progress
01 Jul 2008 21:25:44,060 [Chassis Pool] DEBUG - updateSummaryStatus 9/pon2/7 Reply received: 550 File "/tffs0/images/onte_test.imz.w7" not found or permission problem false false
01 Jul 2008 21:25:44,060 [Chassis Pool] DEBUG - Unable to find DeviceStatus for 9/pon2/7 Reply received
01 Jul 2008 21:25:44,060 [Chassis Pool] ERROR - Ignoring exception when deleting file
01 Jul 2008 21:25:44,080 [Chassis Pool] DEBUG - forward notification module.transfer.progress
01 Jul 2008 21:25:44,080 [Chassis Pool] DEBUG - updateSummaryStatus 9/pon2/7 Command sent: ---> PORT 10,255,0,1,4,84 false false
01 Jul 2008 21:25:44,100 [Chassis Pool] DEBUG - Unable to find DeviceStatus for 9/pon2/7 Command sent
01 Jul 2008 21:25:44,100 [Chassis Pool] DEBUG - forward notification module.transfer.progress
01 Jul 2008 21:25:44,100 [Chassis Pool] DEBUG - updateSummaryStatus 9/pon2/7 Reply received: 200 Port set okay false false
01 Jul 2008 21:25:44,100 [Chassis Pool] DEBUG - Unable to find DeviceStatus for 9/pon2/7 Reply received
01 Jul 2008 21:25:44,120 [Chassis Pool] DEBUG - forward notification module.transfer.progress
01 Jul 2008 21:25:44,120 [Chassis Pool] DEBUG - updateSummaryStatus 9/pon2/7 Command sent: ---> STOR /tffs0/images/onte_test.imz.w7.tmp false false
01 Jul 2008 21:25:44,120 [Chassis Pool] DEBUG - Unable to find DeviceStatus for 9/pon2/7 Command sent
01 Jul 2008 21:25:44,140 [Chassis Pool] DEBUG - forward notification module.transfer.progress
01 Jul 2008 21:25:44,140 [Chassis Pool] DEBUG - updateSummaryStatus 9/pon2/7 Reply received: 150 Opening BINARY mode data connection false false
01 Jul 2008 21:25:44,160 [Chassis Pool] DEBUG - Unable to find DeviceStatus for 9/pon2/7 Reply received
01 Jul 2008 21:25:45,180 [JMX Aggregate Notifier] DEBUG - Sent 19 notifications
01 Jul 2008 21:25:45,580 [Chassis Pool] DEBUG - forward notification module.transfer.progress
01 Jul 2008 21:25:45,580 [Chassis Pool] DEBUG - updateSummaryStatus 9/pon2/7: onte_test.imz.w7 2% false false
01 Jul 2008 21:25:46,860 [Chassis Pool] DEBUG - forward notification module.transfer.progress
01 Jul 2008 21:25:46,860 [Chassis Pool] DEBUG - updateSummaryStatus 9/pon2/7: onte_test.imz.w7 5% false false
01 Jul 2008 21:25:48,580 [JMX Aggregate Notifier] DEBUG - Sent 2 notifications
01 Jul 2008 21:25:50,040 [Chassis Pool] DEBUG - forward notification module.transfer.progress
01 Jul 2008 21:25:50,040 [Chassis Pool] DEBUG - updateSummaryStatus 9/pon2/7: onte_test.imz.w7 7% false false
01 Jul 2008 21:25:51,620 [JMX Aggregate Notifier] DEBUG - Sent 1 notifications
01 Jul 2008 21:25:52,760 [Chassis Pool] DEBUG - forward notification module.transfer.progress
01 Jul 2008 21:25:52,760 [Chassis Pool] DEBUG - updateSummaryStatus 9/pon2/7: onte_test.imz.w7 10% false false
01 Jul 2008 21:25:53,860 [Chassis Pool] DEBUG - forward notification module.transfer.progress
01 Jul 2008 21:25:53,860 [Chassis Pool] DEBUG - updateSummaryStatus 9/pon2/7: onte_test.imz.w7 13% false false
01 Jul 2008 21:25:54,660 [JMX Aggregate Notifier] DEBUG - Sent 2 notifications
01 Jul 2008 21:25:57,340 [Chassis Pool] DEBUG - forward notification module.transfer.progress
01 Jul 2008 21:25:5

Answer 4

Hi Steve

I just ran the following code:

public static void main(String[] args) {
   Logger.setLevel(Level.ALL);
   SecureFileTransferClient ftc = new SecureFileTransferClient();
   try {
      ftc.setRemoteHost("localhost");
      ftc.setUserName("username");
      ftc.setPassword("password");
      ftc.setTimeout(10000);       // timeout is 10 seconds
      ftc.connect();
      ftc.downloadFile("filename", "filename");
   } catch (Throwable t) {
      t.printStackTrace();
   } finally {
      try {
         ftc.disconnect();
      } catch (Throwable t) {
      }
   }
}

I ran it against our own server (Complete FTP), which I'd set up to freeze after a few bytes had been sent.

As expected, a SocketTimeoutException exception was thrown after 10 seconds.

Could you please either try a similar experiment on your machine or describe how the code should be modified to better emulate your scenario.

- Hans (EnterpriseDT)

Answer 5

Thanks much Hans. I will try your code first thing on Monday. Have a great Holiday !
-steve

Answer 6

Hi Steve

I just ran the following code:

public static void main(String[] args) {
   Logger.setLevel(Level.ALL);
   SecureFileTransferClient ftc = new SecureFileTransferClient();
   try {
      ftc.setRemoteHost("localhost");
      ftc.setUserName("username");
      ftc.setPassword("password");
      ftc.setTimeout(10000);       // timeout is 10 seconds
      ftc.connect();
      ftc.downloadFile("filename", "filename");
   } catch (Throwable t) {
      t.printStackTrace();
   } finally {
      try {
         ftc.disconnect();
      } catch (Throwable t) {
      }
   }
}

I ran it against our own server (Complete FTP), which I'd set up to freeze after a few bytes had been sent.

As expected, a SocketTimeoutException exception was thrown after 10 seconds.

Could you please either try a similar experiment on your machine or describe how the code should be modified to better emulate your scenario.

- Hans (EnterpriseDT)

Hi Hans
I tried with FileTransferClient
For download, I do not get any socket exception.
for upload, i got SocketException immediately (which is not timeout exception)
Any other clue? Thanks...-steve

java.net.SocketException: Connection reset
at java.net.SocketInputStream.read(Unknown Source)
at sun.nio.cs.StreamDecoder.readBytes(Unknown Source)
at sun.nio.cs.StreamDecoder.implRead(Unknown Source)
at sun.nio.cs.StreamDecoder.read(Unknown Source)
at java.io.InputStreamReader.read(Unknown Source)
at java.io.BufferedReader.fill(Unknown Source)
at java.io.BufferedReader.readLine(Unknown Source)
at java.io.BufferedReader.readLine(Unknown Source)
at com.enterprisedt.com.ftp.FTPControlSocket.readReply(FTPControlSocket.java:910)
at com.enterprisedt.com.ftp.FTPClient.validateTransfer(FTPClient.java:2114)
at com.enterprisedt.com.ftp.FTPClient.validateTransferOnError(FTPClient.java:2146)
at com.enterprisedt.com.ftp.FTPClient.put(FTPClient.java:2091)
at com.enterprisedt.com.ftp.FTPClient.put(FTPClient.java:2062)
at com.enterprisedt.com.ftp.FileTransferClient.uploadFile(FileTransferClient.java:663)

Answer 7

Could you please post the code you used?

- Hans (EnterpriseDT)

Answer 8

Could you please post the code you used?

- Hans (EnterpriseDT)

Hi Hans

Here is the code. Thanks....

static private final int MaxFTPTimeout = 10000;

FileTransferClient ftp = new FileTransferClient();
ftp.setTimeout(MaxFTPTimeout);
// ftp.set(FTPConnectMode.PASV);
ftp.setUserName(destination.getUserName());
ftp.setPassword(destination.getPassword());

ftp.setContentType(FTPTransferType.BINARY);
// ftp.setProgressMonitor(monitor, MonitorBytes);
ftp.setEventListener(monitor);
com.enterprisedt.util.debug.Logger
      .setLevel(com.enterprisedt.util.debug.Level.DEBUG);
System.setProperty("edtftp.log.log4j", "true");

ftp.setRemoteHost((String) destination.getHost());
if (destination.getPort() != null)
   ftp.setRemotePort(((Integer) destination.getPort()).intValue());

try {
   sendNotification(NotificationType.FTP_PROGRESS, slotNumber
         + ": Connecting via ftp...", token);
   if (ftp.isConnected() == false)
      ftp.connect();
} catch (IOException e) {
   return returnError("Could not connect: " + destination.getHost()
         + " " + e.toString());
} catch (FTPException e) {
   return returnError("FTP protocol error: " + destination.getHost()
         + " " + e.toString());
}
sendNotification(NotificationType.FTP_PROGRESS, slotNumber
      + ": Logging in...", token);
// ftp.login((String)destination.getUserName(),
// (String)destination.getPassword());

try {
   sendNotification(NotificationType.FTP_PROGRESS, slotNumber
         + ": Starting transfer...", token);
} catch (Exception e) {
   return returnError("Problem setting type to BINARY: "
         + destination.getHost() + " " + e.toString());
}

if (!renameFinal) {
   String dir = ((String) destination.getFileName()).substring(0,
         ((String) destination.getFileName()).lastIndexOf("/"));
   try {

      ftp.createDirectory(dir);
   } catch (IOException e) {
      log.error("Unable to create directory: " + dir + " "
            + e.toString());
   } catch (FTPException e) {
      log.error("Unable to create directory: " + dir + " "
            + e.toString());
   } finally {
      try {
         // ftp.put((String)source.getFileName(),
         // (String)destination.getFileName());
         // ftp.uploadFile((String)source.getFileName(),
         // (String)destination.getFileName());
         ftp.downloadFile((String) source.getFileName(),
               (String) destination.getFileName());
         Thread.sleep(FTPsleep);
      } catch (Exception e) {
         return returnError("Problem transferring (dest): "
               + destination.getHost() + " " + e.toString());
      }
   }
}

Answer 9

I just ran your code connecting anonymously to ftp.microsoft.com and downloading the file /bussys/backoffice/reskit/I386/eximwiz/EXIMWIZ.EXE, which is a 2MB file. I unplugged my network cable and received a SocketException shortly afterwards. The log looks as follows:

DEBUG [FTPActiveDataSocket] 11 Jul 2008 12:49:51.985 : accept() succeeded
ERROR [FTPClient] 11 Jul 2008 12:50:08.220 : Caught and rethrowing exception in getDataAfterInitGet() : Connection reset
java.net.SocketException: Connection reset   at java.net.SocketInputStream.read(SocketInputStream.java:168)
   at java.io.DataInputStream.read(DataInputStream.java:132)
   at java.io.BufferedInputStream.read1(BufferedInputStream.java:256)
   at java.io.BufferedInputStream.read(BufferedInputStream.java:317)
   at com.enterprisedt.net.ftp.FTPClient.readChunk(FTPClient.java:3143)
   at com.enterprisedt.net.ftp.FTPClient.getDataAfterInitGet(FTPClient.java:2727)
   at com.enterprisedt.net.ftp.FTPClient.getData(FTPClient.java:2646)
   at com.enterprisedt.net.ftp.FTPClient.get(FTPClient.java:2487)
   at com.enterprisedt.net.ftp.FileTransferClient.downloadFile(FileTransferClient.java:605)
   at com.enterprisedt.net.ftp.FileTransferClient.downloadFile(FileTransferClient.java:585)

MaxFTPTimeout was set to 1000.

Could you please try this exact same test and tell me what happens?

- Hans (EnterpriseDT)

Answer 10

Hi,

I have the same problem :
The uploadFile method detects that I unplug the network cable after 22 minutes, although I have used setTimeout(30*1000)

UPLOAD

DEBUG 2008-09-01 22:36:05,240 [main] ClientFtp:  transfered: 816 [kB] - datarate: 65.1 [kB/s]
cable unplugged
ERROR 2008-09-01 22:58:46,917 [main] ClientFtp:  Could not upload file
java.net.SocketException: No route to host
        at java.net.SocketOutputStream.socketWrite0(Native Method)
        at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:92)
        at java.net.SocketOutputStream.write(SocketOutputStream.java:136)
        at java.io.DataOutputStream.write(DataOutputStream.java:90)
        at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:65)
        at java.io.BufferedOutputStream.write(BufferedOutputStream.java:109)
        at com.enterprisedt.net.ftp.FTPClient.putData(FTPClient.java:2393)
        at com.enterprisedt.net.ftp.FTPClient.put(FTPClient.java:2078)
        at com.enterprisedt.net.ftp.FTPClient.put(FTPClient.java:2060)
        at com.enterprisedt.net.ftp.FileTransferClient.uploadFile(FileTransferClient.java:663)

Note that the downloadFile work at expected with the nominal value passed in setTimeout()

DOWNLOAD

DEBUG 2008-09-02 09:27:56,535 [main] ClientFtp:  transfered: 3615 [kB] - datarate: 423.7 [kB/s]
cable unplugged
ERROR 2008-09-02 09:28:27,297 [main] ClientFtp:  Could not download file
java.net.SocketTimeoutException: Read timed out
        at java.net.SocketInputStream.socketRead0(Native Method)
        at java.net.SocketInputStream.read(SocketInputStream.java:129)
        at java.io.DataInputStream.read(DataInputStream.java:134)
        at java.io.BufferedInputStream.read1(BufferedInputStream.java:254)
        at java.io.BufferedInputStream.read(BufferedInputStream.java:313)
        at com.enterprisedt.net.ftp.FTPClient.readChunk(FTPClient.java:3143)
        at com.enterprisedt.net.ftp.FTPClient.getDataAfterInitGet(FTPClient.java:2727)
        at com.enterprisedt.net.ftp.FTPClient.getData(FTPClient.java:2646)
        at com.enterprisedt.net.ftp.FTPClient.get(FTPClient.java:2487)
        at com.enterprisedt.net.ftp.FileTransferClient.downloadFile(FileTransferClient.java:605)