Software caused connection abort: recv failed

Question

Hi!

Our application polls remote ftp server and download any new files. Generally it works fine, but one particular installation from time to time fails with the exception "java.net.SocketException: Software caused connection abort: recv failed". ftp log shows that the server replied to pasv command, but for some reasons client application can not open data connection. Do you have any idea why it happens?

INFO [GetDirectoryListing] 1 Aug 2008 07:18:06.778 : Creating FTP client, attempt 143
DEBUG [FTPClient] 1 Aug 2008 07:18:06.778 : Class: com.enterprisedt.net.ftp.FTPClient
Version: 2.0.3
Build timestamp: 6-Jun-2008 14:04:32 EST
Java version: 1.4.2_16
CLASSPATH: s:\deploy\edtftpj.jar;s:\deploy\
OS name: Windows 2003
OS arch: x86
OS version: 5.2

INFO [GetDirectoryListing] 1 Aug 2008 07:18:06.778 : Setting remote host
INFO [GetDirectoryListing] 1 Aug 2008 07:18:06.778 : Connecting to server 10.10.12.215
DEBUG [FileTransferClient] 1 Aug 2008 07:18:06.778 : Configured client
DEBUG [FTPClient] 1 Aug 2008 07:18:06.778 : Connecting to /10.10.12.215:21
DEBUG [SocketUtils] 1 Aug 2008 07:18:06.778 : Invoking connect with timeout=60000
DEBUG [SocketUtils] 1 Aug 2008 07:18:06.778 : Connected successfully
DEBUG [FTPControlSocket] 1 Aug 2008 07:18:06.778 : 220 Microsoft FTP Service
INFO [EventListenerImpl] 1 Aug 2008 07:18:06.778 : Reply received: 220 Microsoft FTP Service
DEBUG [FileTransferClient] 1 Aug 2008 07:18:06.778 : Client connected
DEBUG [FileTransferClient] 1 Aug 2008 07:18:06.778 : Logging in
DEBUG [FTPControlSocket] 1 Aug 2008 07:18:06.778 : ---> USER ********
INFO [EventListenerImpl] 1 Aug 2008 07:18:06.778 : Command sent: ---> USER ********
DEBUG [FTPControlSocket] 1 Aug 2008 07:18:06.778 : 331 Password required for ********.
INFO [EventListenerImpl] 1 Aug 2008 07:18:06.778 : Reply received: 331 Password required for ********.
DEBUG [FTPControlSocket] 1 Aug 2008 07:18:06.778 : ---> PASS ********
INFO [EventListenerImpl] 1 Aug 2008 07:18:06.778 : Command sent: ---> PASS ********
DEBUG [FTPControlSocket] 1 Aug 2008 07:18:06.778 : 230 User ******** logged in.
INFO [EventListenerImpl] 1 Aug 2008 07:18:06.778 : Reply received: 230 User ******** logged in.
DEBUG [FileTransferClient] 1 Aug 2008 07:18:06.778 : Logged in
DEBUG [FTPControlSocket] 1 Aug 2008 07:18:06.778 : ---> TYPE I
INFO [EventListenerImpl] 1 Aug 2008 07:18:06.778 : Command sent: ---> TYPE I
DEBUG [FTPControlSocket] 1 Aug 2008 07:18:06.778 : 200 Type set to I.
INFO [EventListenerImpl] 1 Aug 2008 07:18:06.778 : Reply received: 200 Type set to I.
INFO [GetDirectoryListing] 1 Aug 2008 07:18:06.778 : Connected and logged in to server 10.10.12.215
INFO [GetDirectoryListing] 1 Aug 2008 07:18:06.778 : Switch to passive mode
DEBUG [FTPControlSocket] 1 Aug 2008 07:18:06.778 : ---> CWD outbound/FTP/KSS/Inbound
INFO [EventListenerImpl] 1 Aug 2008 07:18:06.778 : Command sent: ---> CWD outbound/FTP/KSS/Inbound
DEBUG [FTPControlSocket] 1 Aug 2008 07:18:06.778 : 250 CWD command successful.
INFO [EventListenerImpl] 1 Aug 2008 07:18:06.778 : Reply received: 250 CWD command successful.
INFO [GetDirectoryListing] 1 Aug 2008 07:18:06.778 : Changed directory to outbound/FTP/KSS/Inbound
INFO [GetDirectoryListing] 1 Aug 2008 07:18:06.778 : Getting current directory listing
DEBUG [FTPControlSocket] 1 Aug 2008 07:18:06.778 : ---> SYST
INFO [EventListenerImpl] 1 Aug 2008 07:18:06.778 : Command sent: ---> SYST
DEBUG [FTPControlSocket] 1 Aug 2008 07:18:06.778 : 215 Windows_NT
INFO [EventListenerImpl] 1 Aug 2008 07:18:06.778 : Reply received: 215 Windows_NT
DEBUG [FTPControlSocket] 1 Aug 2008 07:18:06.778 : ---> PWD
INFO [EventListenerImpl] 1 Aug 2008 07:18:06.778 : Command sent: ---> PWD
DEBUG [FTPControlSocket] 1 Aug 2008 07:18:06.778 : 257 "/outbound/FTP/KSS/Inbound" is current directory.
INFO [EventListenerImpl] 1 Aug 2008 07:18:06.778 : Reply received: 257 "/outbound/FTP/KSS/Inbound" is current directory.
DEBUG [FTPControlSocket] 1 Aug 2008 07:18:06.778 : ---> PASV
INFO [EventListenerImpl] 1 Aug 2008 07:18:06.778 : Command sent: ---> PASV
DEBUG [FTPControlSocket] 1 Aug 2008 07:18:06.778 : 227 Entering Passive Mode (10,10,12,215,14,40).
INFO [EventListenerImpl] 1 Aug 2008 07:18:06.778 : Reply received: 227 Entering Passive Mode (10,10,12,215,14,40).
DEBUG [FTPControlSocket] 1 Aug 2008 07:18:06.778 : Substituting server supplied IP (10.10.12.215) with remote host IP (10.10.12.215)
DEBUG [FTPControlSocket] 1 Aug 2008 07:18:06.778 : ---> LIST
INFO [EventListenerImpl] 1 Aug 2008 07:18:06.778 : Command sent: ---> LIST
DEBUG [FTPControlSocket] 1 Aug 2008 07:18:06.778 : 125 Data connection already open; Transfer starting.
INFO [EventListenerImpl] 1 Aug 2008 07:18:06.778 : Reply received: 125 Data connection already open; Transfer starting.
DEBUG [FTPClient] 1 Aug 2008 07:18:06.809 : Validate transfer on error after exception : Software caused connection abort: recv failed
java.net.SocketException: Software caused connection abort: recv failed
   at java.net.SocketInputStream.socketRead0(Native Method)
   at java.net.SocketInputStream.read(Unknown Source)
   at sun.nio.cs.StreamDecoder$CharsetSD.readBytes(Unknown Source)
   at sun.nio.cs.StreamDecoder$CharsetSD.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.LineNumberReader.readLine(Unknown Source)
   at com.enterprisedt.net.ftp.FTPClient.readLine(FTPClient.java:3171)
   at com.enterprisedt.net.ftp.FTPClient.dir(FTPClient.java:3080)
   at com.enterprisedt.net.ftp.FTPClient.dirDetails(FTPClient.java:3006)
   at com.enterprisedt.net.ftp.FileTransferClient.directoryList(FileTransferClient.java:563)
   at com.enterprisedt.net.ftp.FileTransferClient.directoryList(FileTransferClient.java:549)
   at GetDirectoryListing.main(GetDirectoryListing.java:78)


java.net.SocketException: Software caused connection abort: recv failed
   at java.net.SocketInputStream.socketRead0(Native Method)
   at java.net.SocketInputStream.read(Unknown Source)
   at sun.nio.cs.StreamDecoder$CharsetSD.readBytes(Unknown Source)
   at sun.nio.cs.StreamDecoder$CharsetSD.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.LineNumberReader.readLine(Unknown Source)
   at com.enterprisedt.net.ftp.FTPClient.readLine(FTPClient.java:3171)
   at com.enterprisedt.net.ftp.FTPClient.dir(FTPClient.java:3080)
   at com.enterprisedt.net.ftp.FTPClient.dirDetails(FTPClient.java:3006)
   at com.enterprisedt.net.ftp.FileTransferClient.directoryList(FileTransferClient.java:563)
   at com.enterprisedt.net.ftp.FileTransferClient.directoryList(FileTransferClient.java:549&#

Answer 1

The client is trying to read from the data socket, but is receiving no data from the server (i.e. the directory listing).

Is it possible the directory is empty? It might be a server bug for empty directories.

What happens if you catch the IOException and retry?

Answer 2

Thanks for your quick response!

Directory is not empty, retry helps pretty often, but not always. Sometimes the application performs hundreds of attempts before getting the listing.

I'm trying to narrow down the possible reasons, i.e. is the problem on the server side or on the client side? Is it possible that the server or the client runs out of available sockets? Based on the server response "227 Entering Passive Mode (10,10,12,215,14,40)" it was able allocated the socket and is waiting to accept an incoming connection. The client opened his socket as well, but did not get any data from the server. Why? And why did we get "226 Transfer complete" after the exception? Could you advise what else should be done to solve the issue or at least to understand what is going on?

Thanks,

Gena

Answer 3

It is weird, because it looks like the client has connected to the server on the data port, and is trying to read the listing data when it receives an exception - it looks like the server may have terminated the connection. Probably not a running out of sockets problem, at least that I can see (are you transfering lots of files very quickly?).

If you are able to examine the server logs, that might tell you something useful.

You are getting "transfer complete" so the server thinks it has sent the data. Which is weird. Is it possible that a firewall is interfering and causing packets to be dropped?

It might be worthwhile installing Wireshark and seeing if you can figure out where the problem lies. Wireshark does require a bit of TCP knowledge.

Answer 4

Ethereal (did not know it is Wireshark now) would help, but it happens on production server into customer's environment so it is hardly possible to install and use this tool. Server log does not have any useful information - everything is OK there. Both the server and the client are in the same local network, there are no any firewalls between them.

The application reads the content of the ftp folder, if there are files which names match a mask we download them. If an exception happens the application immediately retries - up to 5 times. This process (read/match/download) is executed every minute.

Answer 5

If the process is executed every minute, perhaps it would be better just to quit at that point and let the next execution take care of it. Perhaps keep a record of failures in a file, and send an alert or email if there are too many or something like that.

It isn't clear why this is happening, but I'm afraid with FTP you do get used to the occasional problem like this that you just have to code around.

Answer 6

Thanks for your support, now it is working stable enough, we slightly increased waiting time between attempts and double check it always starts a brand new session.

Gena