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

Graeme

Posts

37

Joined

Fri Oct 14, 2011 8:14 pm

Location

Dublin

Socket exception when SFTP connection fails

by Graeme » Thu Feb 05, 2015 10:46 pm

I have a question about the the way the ExFTPConnection handles timeouts. It seems that when trying to connect, and a timeout occurs, under certain conditions an exception is caused by another thread. In the log below, Thread 8 tries to connect and fails, and then Thread 5 (with no process ID) tries to "access a disposed object" resulting in a Socket Exception.

[quote]2015-02-05 12:17:15,649 [Thread = 8] [ProcessID = 20228] [ConnectionID = 1] [FileName = (null)] DEBUG EnterpriseDTLog - Processed SSH_MSG_NEWKEYS reply
2015-02-05 12:17:15,650 [Thread = 8] [ProcessID = 20228] [ConnectionID = 1] [FileName = (null)] INFO EnterpriseDTLog - Negotiated new keys successfully
2015-02-05 12:17:15,650 [Thread = 8] [ProcessID = 20228] [ConnectionID = 1] [FileName = (null)] DEBUG EnterpriseDTLog - Key exchange complete
2015-02-05 12:17:15,652 [Thread = 8] [ProcessID = 20228] [ConnectionID = 1] [FileName = (null)] DEBUG EnterpriseDTLog - Sent SSH_MSG_SERVICE_REQUEST 'ssh-userauth'
2015-02-05 12:17:15,652 [Thread = 8] [ProcessID = 20228] [ConnectionID = 1] [FileName = (null)] DEBUG EnterpriseDTLog - Waiting for packet
2015-02-05 12:17:15,654 [Thread = 8] [ProcessID = 20228] [ConnectionID = 1] [FileName = (null)] DEBUG EnterpriseDTLog - Packet arrived
2015-02-05 12:17:15,655 [Thread = 8] [ProcessID = 20228] [ConnectionID = 1] [FileName = (null)] DEBUG EnterpriseDTLog - Starting user authentication
2015-02-05 12:17:15,655 [Thread = 8] [ProcessID = 20228] [ConnectionID = 1] [FileName = (null)] DEBUG EnterpriseDTLog - Password authentication
2015-02-05 12:17:15,655 [Thread = 8] [ProcessID = 20228] [ConnectionID = 1] [FileName = (null)] DEBUG EnterpriseDTLog - Sent SSH_MSG_USERAUTH_REQUEST
2015-02-05 12:17:15,656 [Thread = 8] [ProcessID = 20228] [ConnectionID = 1] [FileName = (null)] DEBUG EnterpriseDTLog - Waiting for packet
2015-02-05 12:17:15,675 [Thread = 8] [ProcessID = 20228] [ConnectionID = 1] [FileName = (null)] DEBUG EnterpriseDTLog - Packet arrived
2015-02-05 12:17:15,675 [Thread = 8] [ProcessID = 20228] [ConnectionID = 1] [FileName = (null)] DEBUG EnterpriseDTLog - ProcessAuthenticationResponse: SSH_MSG_USERAUTH_SUCCESS
2015-02-05 12:17:15,676 [Thread = 8] [ProcessID = 20228] [ConnectionID = 1] [FileName = (null)] DEBUG EnterpriseDTLog - User authentication successful
2015-02-05 12:17:15,678 [Thread = 8] [ProcessID = 20228] [ConnectionID = 1] [FileName = (null)] DEBUG EnterpriseDTLog - Sent SSH_MSG_CHANNEL_OPEN
2015-02-05 12:17:15,679 [Thread = 8] [ProcessID = 20228] [ConnectionID = 1] [FileName = (null)] INFO EnterpriseDTLog - Waiting for SSH channel to be opened
2015-02-05 12:17:15,681 [Thread = 9] [ProcessID = (null)] [ConnectionID = (null)] [FileName = (null)] DEBUG EnterpriseDTLog - ProcessPacket: status= 2, pt=SSH_MSG_CHANNEL_OPEN_CONFIRMATION
2015-02-05 12:17:15,682 [Thread = 9] [ProcessID = (null)] [ConnectionID = (null)] [FileName = (null)] DEBUG EnterpriseDTLog - OpenSFTP pt=SSH_MSG_CHANNEL_OPEN_CONFIRMATION
2015-02-05 12:17:15,682 [Thread = 9] [ProcessID = (null)] [ConnectionID = (null)] [FileName = (null)] DEBUG EnterpriseDTLog - Remote window size set to 262144
2015-02-05 12:17:15,683 [Thread = 9] [ProcessID = (null)] [ConnectionID = (null)] [FileName = (null)] DEBUG EnterpriseDTLog - Remote max packet size=65536
2015-02-05 12:17:15,683 [Thread = 9] [ProcessID = (null)] [ConnectionID = (null)] [FileName = (null)] DEBUG EnterpriseDTLog - Setting packet size=65535
2015-02-05 12:17:15,683 [Thread = 9] [ProcessID = (null)] [ConnectionID = (null)] [FileName = (null)] DEBUG EnterpriseDTLog - Sending SSH_MSG_CHANNEL_REQUEST
2015-02-05 12:17:15,689 [Thread = 8] [ProcessID = 20228] [ConnectionID = 1] [FileName = (null)] INFO EnterpriseDTLog - Waiting for SSH channel to be opened
2015-02-05 12:17:15,699 [Thread = 8] [ProcessID = 20228] [ConnectionID = 1] [FileName = (null)] INFO EnterpriseDTLog - Waiting for SSH channel to be opened
2015-02-05 12:17:15,709 [Thread = 8] [ProcessID = 20228] [ConnectionID = 1] [FileName = (null)] INFO EnterpriseDTLog - Waiting for SSH channel to be opened
2015-02-05 12:17:15,719 [Thread = 8] [ProcessID = 20228] [ConnectionID = 1] [FileName = (null)] INFO EnterpriseDTLog - Waiting for SSH channel to be opened
2015-02-05 12:17:15,729 [Thread = 8] [ProcessID = 20228] [ConnectionID = 1] [FileName = (null)] INFO EnterpriseDTLog - Waiting for SSH channel to be opened
2015-02-05 12:17:15,739 [Thread = 8] [ProcessID = 20228] [ConnectionID = 1] [FileName = (null)] INFO EnterpriseDTLog - Waiting for SSH channel to be opened
2015-02-05 12:17:15,749 [Thread = 8] [ProcessID = 20228] [ConnectionID = 1] [FileName = (null)] INFO EnterpriseDTLog - Waiting for SSH channel to be opened
2015-02-05 12:17:15,759 [Thread = 8] [ProcessID = 20228] [ConnectionID = 1] [FileName = (null)] INFO EnterpriseDTLog - Waiting for SSH channel to be opened
2015-02-05 12:17:15,769 [Thread = 8] [ProcessID = 20228] [ConnectionID = 1] [FileName = (null)] INFO EnterpriseDTLog - Waiting for SSH channel to be opened
2015-02-05 12:17:15,779 [Thread = 8] [ProcessID = 20228] [ConnectionID = 1] [FileName = (null)] ERROR EnterpriseDTLog - Timed out waiting for SSH channel to be opened
2015-02-05 12:17:15,789 [Thread = 8] [ProcessID = 20228] [ConnectionID = 1] [FileName = (null)] ERROR EnterpriseDTLog - Failed to connect - closing connection
EnterpriseDT.Net.Ftp.Ssh.SFTPException: Timed out waiting for SSH channel to be opened
at EnterpriseDT.Net.Ftp.Ssh.SSHSCPClient.CheckTimeout(DateTime start, String msg)
at EnterpriseDT.Net.Ftp.Ssh.SSHFTPClient.Connect()
2015-02-05 12:17:15,811 [Thread = 5] [ProcessID = (null)] [ConnectionID = (null)] [FileName = (null)] ERROR EnterpriseDTLog - Cannot access a disposed object.
Object name: 'System.Net.Sockets.Socket'.
System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'System.Net.Sockets.Socket'.
at System.Net.Sockets.Socket.EndReceive(IAsyncResult asyncResult, SocketError& errorCode)
at System.Net.Sockets.Socket.EndReceive(IAsyncResult asyncResult)
at reJ5auFFO0Pytlg0EZ9.Wx89SfFDoRyE74JQJZN.QhZJQWlTHC(IAsyncResult )
2015-02-05 12:17:15,812 [Thread = 8] [ProcessID = 20228] [ConnectionID = 1] [FileName = (null)] DEBUG EnterpriseDTLog - Closing connection (instance=0)
2015-02-05 12:17:15,813 [Thread = 8] [ProcessID = 20228] [ConnectionID = 1] [FileName = (null)] DEBUG EnterpriseDTLog - Quit() called
2015-02-05 12:17:15,814 [Thread = 8] [ProcessID = 20228] [ConnectionID = 1] [FileName = (null)] DEBUG EnterpriseDTLog - Closing channel 0
2015-02-05 12:17:15,830 [Thread = 8] [ProcessID = 20228] [ConnectionID = 1] [FileName = (null)] WARN EnterpriseDTLog - Caught exception closing connection: Cannot access a disposed object.
Object name: 'System.Net.Sockets.Socket'.
[/quote]

Is there any way to avoid this or, if not, is it safe to ignore this exception and to filter it out of our logs?
no avatar
User

support2

Posts

3987

Joined

Tue May 18, 2004 8:30 am

Re: Socket exception when SFTP connection fails

by support2 » Thu Feb 05, 2015 11:44 pm

Yes, you could ignore this. There's a number of threads, and the thread reading from the socket doesn't know it is closed at this point.

Who is online

Users browsing this forum: No registered users and 24 guests

Powered by phpBB ® | phpBB3 Style by KomiDesign