Understanding the Exceptions in the EDT Log

Question

We have been using the EDTFtpPro.Net FTP client library for quite some time in a multi-threaded windows service application. We are currently in the process of reviewing the debug log generated by it and see a couple of exceptions and lines of log which we would like to eliminate. Could you please clarify as to what or if we are doing something wrong in our applications for these to appear. Thanks in advance:

* An established connection was aborted by the software in your host machine
* Attempt to close unconnected passive data-channel
* Status=ShutdownSSL
* OnReceive - (An existing connection was forcibly closed by the remote host) - closing

One thing to note is that sometimes these exceptions get propagated to our application and sometimes it gets handled within EDT component itself.

We get a lot of these exceptions intermittently, although the file downloads do succeed eventually. Our application is written is such that we do retries for unsuccessful downloads.

Sample log containing these exceptions:

DEBUG [FTPControlSocket] 25 Feb 2011 10:34:13.593 : ---> PASV
DEBUG [FTPControlSocket] 25 Feb 2011 10:34:13.593 : 250 DELE command successful.
DEBUG [FTPControlSocket] 25 Feb 2011 10:34:13.593 : 213 20110225151925.462
DEBUG [FTPControlSocket] 25 Feb 2011 10:34:13.609 : 227 Entering Passive Mode (X,X,X,X,121,24).
DEBUG [FTPControlSocket] 25 Feb 2011 10:34:13.609 : Server supplied address=X.X.X.X
DEBUG [FTPControlSocket] 25 Feb 2011 10:34:13.609 : Server supplied port=31000
DEBUG [FTPControlSocket] 25 Feb 2011 10:34:13.609 : autoPassiveIPSubstitution=True
DEBUG [FTPControlSocket] 25 Feb 2011 10:34:13.609 : remoteAddr=X.X.X.X
DEBUG [FTPControlSocket] 25 Feb 2011 10:34:13.609 : Substituting server supplied IP (X.X.X.X) with remote host IP (X.X.X.X)
DEBUG [HostNameResolver] 25 Feb 2011 10:34:13.609 : Resolving X.X.X.X
DEBUG [HostNameResolver] 25 Feb 2011 10:34:13.609 : X.X.X.X resolved to X.X.X.X
DEBUG [ExFTPControlSocket] 25 Feb 2011 10:34:13.609 : Connecting directly to ftp-server X.X.X.X:31000
DEBUG [SocketController] 25 Feb 2011 10:34:13.609 : Dispose()
DEBUG [SocketController] 25 Feb 2011 10:34:13.609 : CloseConnection(e=null)
DEBUG [SocketController] 25 Feb 2011 10:34:13.609 : Dispose()
DEBUG [SocketController] 25 Feb 2011 10:34:13.609 : CloseConnection(e=null)
DEBUG [ExFTPPassiveDataSocket] 25 Feb 2011 10:34:13.609 : Created passive data-socket: ProxyConnector=
DEBUG [SSLFTPPassiveDataSocket] 25 Feb 2011 10:34:13.609 : Created passive data-socket: Protocol=Ssl3, Tls1, CompatibilityFlags=Standard, UseSSLClosure=True, WaitOnClose=True
DEBUG [FTPControlSocket] 25 Feb 2011 10:34:13.609 : ---> RETR 20110225/File1.hbt
DEBUG [FTPControlSocket] 25 Feb 2011 10:34:13.625 : 150 Opening BINARY mode data connection for 20110225/File1.hbt.
DEBUG [SSLFTPPassiveDataSocket] 25 Feb 2011 10:34:13.625 : Beginning Ssl3, Tls1 handshake on passive data-channel
DEBUG [SocketController] 25 Feb 2011 10:34:13.625 : Processing hello
DEBUG [FTPControlSocket] 25 Feb 2011 10:34:13.656 : 226 Transfer complete. 1033 bytes transferred. 1033 bps.
DEBUG [FTPControlSocket] 25 Feb 2011 10:34:13.656 : ---> SIZE 20110225/File2.hbt
DEBUG [SecureSocket] 25 Feb 2011 10:34:13.672 : OnHandshakeComplete(True,null)
DEBUG [SocketController] 25 Feb 2011 10:34:13.687 : Status=ShutdownSSL
WARN [SocketController] 25 Feb 2011 10:34:13.687 : OnReceive - (An established connection was aborted by the software in your host machine) - closing
DEBUG [SocketController] 25 Feb 2011 10:34:13.687 : CloseConnection(e=An established connection was aborted by the software in your host machine)
DEBUG [SocketController] 25 Feb 2011 10:34:13.687 : Closed socket
DEBUG [TransferBuffer] 25 Feb 2011 10:34:13.687 : Close() called when open
DEBUG [SecureSocket] 25 Feb 2011 10:34:13.687 : OnHandshakeComplete(False,An established connection was aborted by the software in your host machine)
ERROR [SecureSocket] 25 Feb 2011 10:34:13.687 : Exception during handshake: An established connection was aborted by the software in your host machine
DEBUG [SSLFTPPassiveDataSocket] 25 Feb 2011 10:34:13.687 : Attempt to close unconnected passive data-channel.
ERROR [FTPClient] 25 Feb 2011 10:34:13.687 : Caught exception
ERROR [FTPClient] 25 Feb 2011 10:34:13.687 : System.Net.Sockets.SocketException: An established connection was aborted by the software in your host machine
ERROR [FTPClient] 25 Feb 2011 10:34:13.687 : at UuVpDZeDPo1i3iaI8SX.M3VxBtelCOZki4qP1aD.nuVIpfcMw(sCNkaued7WpGMn82SFj )
ERROR [FTPClient] 25 Feb 2011 10:34:13.687 : at UuVpDZeDPo1i3iaI8SX.M3VxBtelCOZki4qP1aD.TAxyLAhN4(SecureProtocol )
ERROR [FTPClient] 25 Feb 2011 10:34:13.687 : at VmkQBpYkI83jlyITHRm.BQXr9MYb69n7ALj4hiv.get_DataStream()
ERROR [FTPClient] 25 Feb 2011 10:34:13.687 : at EnterpriseDT.Net.Ftp.ExFTPClient.GetInputStream()
ERROR [FTPClient] 25 Feb 2011 10:34:13.687 : at EnterpriseDT.Net.Ftp.FTPClient.MZJphWWbc(String , String )



----------------------------------
DEBUG [FTPControlSocket] 25 Feb 2011 10:34:07.844 : ---> RETR 20110225/File1.rdy
DEBUG [FTPControlSocket] 25 Feb 2011 10:34:07.844 : 213 92
DEBUG [FTPControlSocket] 25 Feb 2011 10:34:07.859 : 150 Opening BINARY mode data connection for 20110225/File2.rdy.
DEBUG [SSLFTPPassiveDataSocket] 25 Feb 2011 10:34:07.859 : Beginning Ssl3, Tls1 handshake on passive data-channel
DEBUG [ExFTPConnection] 25 Feb 2011 10:34:07.859 : Attempt #1
DEBUG [FTPConnection] 25 Feb 2011 10:34:07.859 : DownloadFile(E:\Data\ECLInbox\Branch\Received\20110225\00001_c5254e8e-dd84-4500-a7de-d3a0f736e79a.GUID,20110225/File4.rdy)
DEBUG [FTPControlSocket] 25 Feb 2011 10:34:07.859 : ---> SIZE 20110225/File3.rdy
DEBUG [FTPControlSocket] 25 Feb 2011 10:34:07.875 : 150 Opening BINARY mode data connection for 20110225/File1.rdy.
DEBUG [SSLFTPPassiveDataSocket] 25 Feb 2011 10:34:07.875 : Beginning Ssl3, Tls1 handshake on passive data-channel
DEBUG [SocketController] 25 Feb 2011 10:34:07.875 : Processing hello
DEBUG [SocketController] 25 Feb 2011 10:34:07.891 : Processing hello
DEBUG [FTPControlSocket] 25 Feb 2011 10:34:07.891 : 213 814
DEBUG [FTPControlSocket] 25 Feb 2011 10:34:07.891 : ---> PASV
DEBUG [SecureSocket] 25 Feb 2011 10:34:07.922 : OnHandshakeComplete(True,null)
DEBUG [SSLFTPPassiveDataSocket] 25 Feb 2011 10:34:07.922 : Handshake complete
DEBUG [SocketController] 25 Feb 2011 10:34:07.937 : Dispose()
DEBUG [SocketController] 25 Feb 2011 10:34:07.937 : CloseConnection(e=null)
DEBUG [SocketController] 25 Feb 2011 10:34:07.937 : Dispose()
DEBUG [SocketController] 25 Feb 2011 10:34:07.937 : CloseConnection(e=null)
DEBUG [SocketController] 25 Feb 2011 10:34:07.937 : Dispose()
DEBUG [SocketController] 25 Feb 2011 10:34:07.937 : CloseConnection(e=null)
DEBUG [SocketController] 25 Feb 2011 10:34:07.937 : Dispose()
DEBUG [SocketController] 25 Feb 2011 10:34:07.937 : CloseConnection(e=null)
DEBUG [SocketController] 25 Feb 2011 10:34:07.937 : Dispose()
DEBUG [SocketController] 25 Feb 2011 10:34:07.937 : CloseConnection(e=null)
DEBUG [SecureSocket] 25 Feb 2011 10:34:07.937 : OnHandshakeComplete(True,null)
DEBUG [SSLFTPPassiveDataSocket] 25 Feb 2011 10:34:07.937 : Handshake complete
DEBUG [Socket

Answer 1

The first thing to note is that two of these messages are debug level messages, and aren't errors at all:

- Attempt to close unconnected passive data-channel
- Status=ShutdownSSL

The error "An existing connection was forcibly closed by the remote host" is because the remote client has abruptly close the TCP connection. There's not much you can do about that.

I'm not sure about "An established connection was aborted by the software in your host machine". etFTPnet/PRO has closed the connection, but possibly because of an error in the control connection.

You do need to be careful in a multi-threaded environment to ensure that a single instance of SecureFTPConnection is only accessed by a single thread at a time.

Answer 2

Thanks for the input. Will take a look. One thing which would be immensely helpful, especially in a multi-threaded application would be some way to identify the thread id of a log statement. Currently, it is very difficult to trace the loggers for a particular connection. Is there some way to include this in the logs? I know log4net supports this and we use it often.

Answer 3

Currently, no.

However you can subscribe to the LogMessageReceived event on EnterpriseDT.Util.Debug.Logger, which will allow you to direct the logging output wherever you like.

So you could choose to direct output to log4net via this event.

We've been meaning to add a property for thread ids however and will do it soon.