Discuss (FTP), (FTP on .NET CF) and (FTPS, SFTP and SCP).
no avatar
User

george.ranjan

Posts

2

Joined

Tue Sep 21, 2010 6:53 am

Understanding the Exceptions in the EDT Log

by george.ranjan » Sat Mar 12, 2011 12:48 am

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 [SocketController] 25 Feb 2011 10:34:07.937 : Status=ShutdownSSL
DEBUG [SocketController] 25 Feb 2011 10:34:07.937 : OnReceive closing (size == 0)
DEBUG [SocketController] 25 Feb 2011 10:34:07.937 : CloseConnection(e=null)
DEBUG [SocketController] 25 Feb 2011 10:34:07.937 : Shut down socket
DEBUG [SocketController] 25 Feb 2011 10:34:07.937 : Closed socket
DEBUG [TransferBuffer] 25 Feb 2011 10:34:07.937 : Close() called when open
DEBUG [SocketController] 25 Feb 2011 10:34:07.953 : Status=ShutdownSSL
WARN [SocketController] 25 Feb 2011 10:34:07.953 : OnReceive - (An existing connection was forcibly closed by the remote host) - closing
DEBUG [SocketController] 25 Feb 2011 10:34:07.953 : CloseConnection(e=An existing connection was forcibly closed by the remote host)
DEBUG [SocketController] 25 Feb 2011 10:34:07.953 : Closed socket
DEBUG [TransferBuffer] 25 Feb 2011 10:34:07.953 : Close() called when open
DEBUG [SecureSocket] 25 Feb 2011 10:34:07.953 : OnHandshakeComplete(False,An existing connection was forcibly closed by the remote host)

DEBUG [BandwidthThrottler] 25 Feb 2011 10:34:07.969 : rate=17695.652173913
DEBUG [SSLFTPPassiveDataSocket] 25 Feb 2011 10:34:07.969 : Attempt to close unconnected passive data-channel.





I can send more detailed log if required via email.

Any help would be greatly appreciated.

Thanks
no avatar
User

support2

Posts

3987

Joined

Tue May 18, 2004 8:30 am

Re: Understanding the Exceptions in the EDT Log

by support2 » Mon Mar 14, 2011 11:32 am

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.
no avatar
User

george.ranjan

Posts

2

Joined

Tue Sep 21, 2010 6:53 am

Thread Id or some thread reference in log

by george.ranjan » Mon Mar 14, 2011 8:42 pm

no avatar
User

support2

Posts

3987

Joined

Tue May 18, 2004 8:30 am

Re: Thread Id or some thread reference in log

by support2 » Mon Mar 14, 2011 9:56 pm


Who is online

Users browsing this forum: No registered users and 26 guests

Powered by phpBB ® | phpBB3 Style by KomiDesign
cron