Our Products:   CompleteFTP  edtFTPnet/Free  edtFTPnet/PRO  edtFTPj/Free  edtFTPj/PRO
0 votes
882 views
in .NET FTP by (1.3k points)
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?

1 Answer

0 votes
by (161k points)
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.

Categories

...