I am receiving a weird exception during file upload (using ftp4j library) from a specific workstation.
After file has uploaded (100%) i receive a read timed out exception. Here it is:
2015-03-20 18:14:43 INFO TranferFileFtp4j:760 - FTP Server supports resume. Trying to upload file
2015-03-20 18:14:43 INFO Ftp4jListener:38 - TRANSFER-STATUS: File transfer started
2015-03-20 18:14:43 INFO Ftp4jListener:47 - File: 152818571.zip | Bytes transfered 65536 Percentage: 0.024173772%
...
2015-03-20 18:20:08 INFO Ftp4jListener:47 - File: 153740599.zip | Bytes transfered 244383744 Percentage: 99.89077%
2015-03-20 18:20:08 INFO Ftp4jListener:47 - File: 153740599.zip | Bytes transfered 244449280 Percentage: 99.91756%
2015-03-20 18:20:08 INFO Ftp4jListener:47 - File: 153740599.zip | Bytes transfered 244514816 Percentage: 99.94434%
2015-03-20 18:20:08 INFO Ftp4jListener:47 - File: 153740599.zip | Bytes transfered 244580352 Percentage: 99.97113%
2015-03-20 18:20:08 INFO Ftp4jListener:47 - File: 153740599.zip | Bytes transfered 244645888 Percentage: 99.99792%
2015-03-20 18:20:08 INFO Ftp4jListener:47 - File: 153740599.zip | Bytes transfered 244650979 Percentage: 100.0%
2015-03-20 18:20:18 INFO TranferFileFtp4j:803 - Failed to send File! IOException other exceptionRead timed out - null
java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(Unknown Source)
at java.net.SocketInputStream.read(Unknown Source)
at sun.security.ssl.InputRecord.readFully(Unknown Source)
at sun.security.ssl.InputRecord.read(Unknown Source)
at sun.security.ssl.SSLSocketImpl.readRecord(Unknown Source)
at sun.security.ssl.SSLSocketImpl.readDataRecord(Unknown Source)
at sun.security.ssl.AppInputStream.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 sun.nio.cs.StreamDecoder.read0(Unknown Source)
at sun.nio.cs.StreamDecoder.read(Unknown Source)
at java.io.InputStreamReader.read(Unknown Source)
at it.sauronsoftware.ftp4j.NVTASCIIReader.readLine(NVTASCIIReader.java:105)
at it.sauronsoftware.ftp4j.FTPCommunicationChannel.read(FTPCommunicationChannel.java:142)
at it.sauronsoftware.ftp4j.FTPCommunicationChannel.readFTPReply(FTPCommunicationChannel.java:187)
at it.sauronsoftware.ftp4j.FTPClient.upload(FTPClient.java:2797)
at it.sauronsoftware.ftp4j.FTPClient.upload(FTPClient.java:2586)
at com.npap.network.TranferFileFtp4j.uploadFileFtps5(TranferFileFtp4j.java:765)
at com.npap.utils.ProcessDicomFiles.sendZippFiles(ProcessDicomFiles.java:215)
at com.npap.scheduler.MainJob.execute(MainJob.java:97)
at org.quartz.core.JobRunShell.run(JobRunShell.java:202)
at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573)
java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(Unknown Source)
at java.net.SocketInputStream.read(Unknown Source)
at sun.security.ssl.InputRecord.readFully(Unknown Source)
at sun.security.ssl.InputRecord.read(Unknown Source)
at sun.security.ssl.SSLSocketImpl.readRecord(Unknown Source)
at sun.security.ssl.SSLSocketImpl.readDataRecord(Unknown Source)
at sun.security.ssl.AppInputStream.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 sun.nio.cs.StreamDecoder.read0(Unknown Source)
at sun.nio.cs.StreamDecoder.read(Unknown Source)
at java.io.InputStreamReader.read(Unknown Source)
at it.sauronsoftware.ftp4j.NVTASCIIReader.readLine(NVTASCIIReader.java:105)
at it.sauronsoftware.ftp4j.FTPCommunicationChannel.read(FTPCommunicationChannel.java:142)
at it.sauronsoftware.ftp4j.FTPCommunicationChannel.readFTPReply(FTPCommunicationChannel.java:187)
at it.sauronsoftware.ftp4j.FTPClient.disconnect(FTPClient.java:1133)
at com.npap.network.TranferFileFtp4j.uploadFileFtps5(TranferFileFtp4j.java:826)
at com.npap.utils.ProcessDicomFiles.sendZippFiles(ProcessDicomFiles.java:215)
at com.npap.scheduler.MainJob.execute(MainJob.java:97)
at org.quartz.core.JobRunShell.run(JobRunShell.java:202)
at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573)
And here is the code:
ftpClient = Ftp4jUtility.ftpsConnect(SERVER_MACHINE, PORT, SERVER_USERNAME, SERVER_PASSWORD, stdId);
ftpClient.changeDirectory(config.getFtpRemoteFolderUploads());
if(ftpClient.isResumeSupported()) {
ftpClient.upload(localFile, writtenBytes, new Ftp4jListener(localFile.length(), localFile.getName()));
} else {
ftpClient.upload(localFile, new Ftp4jListener(localFile.length(), localFile.getName()));
}
completed = true;
} catch (FTPAbortedException e) {
....
break;
} catch (FTPDataTransferException ex1) {
studyDetailsDAO.updateStudyIsInProgress(stdId, false);
ex1.printStackTrace();
....
} catch (FTPException ex1) {
ex1.printStackTrace();
....
} catch (FTPIllegalReplyException ex1) {
ex1.printStackTrace();
...
} catch (IOException ex1) {
log.info("Failed to send File! IOException " + ex1.getMessage());
ex1.printStackTrace();
} catch (IllegalStateException ex1) {
...
} finally {
if(ftpClient!=null && ftpClient.isConnected()) {
try {
ftpClient.disconnect(true);
} catch (Throwable t) {
t.printStackTrace();
}
}
}
I am receiving this exception: IOException - read timed out! Any ideas what is it causing this? or how to proceed for debugging?
The weird thing is that all ftp operations are working! I am also able to start and practically upload the file, however at the end of the ftpClient.upload operation i am receiving this time out!
I have also checked and found that i have this particular problem from a specific workstation. I have even tried to upload a file using filezilla and i am receiving a similar exception (read timed out). So i guess it is a network or firewall issue... Any ideas?
Any ideas?
Possible problem
FTP protocol uses separate control and data TCP connections between the client and the server. During file transfers, the data connection is busy, but the control connection is idle. According with your log the transfer takes 15 minutes. It means the control connection is idle for that period of time. Some firewalls or network routers can disconnect connections without any activity for a certain period of time. Looks like this is the case because readFTPReply tries to read from the control connection and throws "Read timed out".
How to debug
You can make a dump of traffic on the client side by Wireshark or tcpdump and try to find out why the control connection is disconnected.
How to fix
I can see two ways to fix the problem:
You can ping the server sending NOOP command over the control connection to make some activity during transfers and reset the connection's idle timer in firewalls/routers. I'm not sure if ftp4j can do that. But you can switch to Apache FTPClient and use setControlKeepAliveTimeout.
You can try to update/change firewalls/routers.