Renci.SshNet.Common.SshOperationTimeoutException on Disconnect()

Sep 4, 2012 at 2:09 PM

Hi all,

We get the following exception sometimes upon calling Disconnect():

Renci.SshNet.Common.SshOperationTimeoutException

Session operation has timed out

Stack:

   at Renci.SshNet.Session.WaitHandle(WaitHandle waitHandle)

   at Renci.SshNet.BaseClient.Disconnect()

   at RiksTV.Csl.FtpManager.InboundSftpTransmitter.GetResponseDirectoryListing() in C:\Users\140580anzh_adm\Documents\Visual Studio 2010\Projects\RiksTV-OTT-2-Mnt\RiksTV.Csl.FtpManager\InboundSftpTransmitter.cs:line 109

   at RiksTV.Csl.InboundFtpCommunicator.InboundFtpCommunicator.ProcessFtpFolderForMessages(FtpConfiguration ftpConfiguration, ArchivingConfiguration archivingConfiguration, CancellationTokenSource cancelSource) in C:\Users\140580anzh_adm\Documents\Visual Studio 2010\Projects\RiksTV-OTT-2-Mnt\Inbound Flow\RiksTV.Csl.InboundFtpCommunicator\InboundFtpCommunicator.cs:line 174

 

What we believe to have found out is that the exception only happens if the directory we checked for files has been empty. The code in question is:

string host, filePath;

            FtpHelper.ParseFtpUri(fileUri, out host, out filePath);

 

            SftpClient sftp = null;

            MemoryStream stream;

 

            try

            {

                sftp = SftpHelper.Connect(host, _configuration.Login, _configuration.Password,

                    _configuration.SftpClientPrivateKeyFilePath);

 

                stream = new MemoryStream();

                sftp.DownloadFile(filePath, stream);

                stream.Seek(0, SeekOrigin.Begin);

            }

            finally

            {

                if (sftp != null && sftp.IsConnected)

                {

                    sftp.Disconnect();

                    sftp.Dispose();

                }

            }

Any help and/or hints are greatly appreciated!

Sep 9, 2012 at 2:04 AM

Hello

What exactly do you mean by "What we believe to have found out is that the exception only happens if the directory we checked for files has been empty."?

Also you have a bug in the finally, if sftp.IsConnected == false, example due to exception during connecting, dispose will not be called.

Sep 10, 2012 at 10:56 AM

Thanks for the bug hint, we had found it too. By the way, could this bug have caused us a memory  leak?

Back to the original problem in question:

We get the exception (on disconnect) only if the catalogue we are accessing is empty. If there are files in the catalogue we don't get the exception once we disconnect. Does this answer your question?

Sep 10, 2012 at 11:51 AM

If you are looking for some tips to prevent memory leaks in .NET (VB/C#), you must read about the using statement.

  1. using Statement (C# Reference)
  2. Understanding the 'using' statement in C#

Also, to understanding how try/finally works with disposable objects in case of an exception:

  1. try-finally (C# Reference)

<tt>The finally block is useful for cleaning up any resources that are allocated in the try block, and for running any code that must execute even if an exception occurs in the try block.</tt>

It is well worth your time to get to know what classes implement IDisposable. One way of doing this is to right click the class name, for example MemoryStream, and Go To Definition (F12), then scroll up and look at the "class MemoryStream"-part and see what it inherits from. You can also use Go To Definition on the classes that is being inherited to see if any of them inherits from IDisposable. So in case of MemoryStream, it inherits from Stream, which again inherits from IDisposable. So any class that inherits from Stream, like FileStream, MemoryStream, NetworkStream, can be used with the using-keyword.

Another example to know about is the TextReader and TextWriter base classes, File.OpenText() returns a StreamReader, which inherits from TextReader, which also inherits from IDisposable.

If your class is using objects that inherits from IDisposable (properties, fields), it should implement IDisposable itself. So in the case of an unrelated exception, inside a using-block, that object will not leak.

You can google .NET Memory leaks. Also, here is a nice post for using WinDBG to find leaks: Spotting a Memory Leak With WinDBG in .NET

With that out of the way, I will tell you there is 1 more bug in the code you pasted.


  1. Can you reproduce this exception reliably?
  2. Is the application multithreaded?
  3. Are you catching and ignoring any exceptions?
  4. Can you make list of calls to SftpClient in the order they are called? And which calls are wrapped in try/catch?
Sep 13, 2012 at 1:14 PM

1. Yes, every 5th minute, and several environments

2. No, single threaded

3. No

4. Well, except the code above,no further calls are made:

  1. We create the client with SftpHelper.Connect
  2. Is called to download all files from the accessed directory: sftp.DownloadFile

Rough code structure

try

{

	InboundSftpTransmitter.GetResponseDirectoryListing();  // the exception happens in 
GetResponseDirectoryListing
} catch (Exception ex) { _logger.LogException(ex); }

 

Sep 13, 2012 at 4:45 PM

Very interesting...

In this issue I wrote some XML, http://sshnet.codeplex.com/workitem/1303 What does the log give you? What server version?

Nov 15, 2012 at 2:45 PM
Edited Nov 15, 2012 at 2:47 PM

Hi Kenneth,

I am sorry for not replying for so long. We still have the issue of course, so nothing has got solved yet. We did however refactor the code (was pretty bad stuff). We haven't used your XML, where would we add/apply it to?

We have been investigating this further and have actually started to debug your library. Now the most peculiar thing:

When we run your library in the debugger, we don't get a time out on disconnect. If we run it without debugger (e.g. the  ListDirectoryTest) we get the timeout on disconnect.

The exception is throw in the WaitHandle method:

 

internal void WaitHandle(WaitHandle waitHandle)
        {
            var waitHandles = new WaitHandle[]
                {
                    this._exceptionWaitHandle,
                    waitHandle,
                };

            var index = EventWaitHandle.WaitAny(waitHandles, this.ConnectionInfo.Timeout);

            if (index < 1)
            {
                throw this._exception;
            }
            else if (index > 1) // <- Index gets larger than one, but only if not run in the debugger!
            {
                this.SendDisconnect(DisconnectReason.ByApplication, "Operation timeout");

                throw new SshOperationTimeoutException("Session operation has timed out"); //<- here the exception is thrown...
            }
        }

 

Why this is the case we don't know or understand (yet). It would be great if you could enlighten us and explain:

- why your library behaves the way it does

- what could be done about it

Nov 16, 2012 at 12:54 PM

Ok we now added the XML you mentionded. This is the output:

SshNet.Logging Verbose: 1 : Initiating connect to '139.117.102.20:22'.

SshNet.Logging Verbose: 1 : Server version '1.99' on 'OpenSSH_4.2'.

SshNet.Logging Verbose: 1 : ReceiveMessage from server: 'KeyExchangeInitMessage': 'SSH_MSG_KEXINIT'.

SshNet.Logging Verbose: 1 : SendMessage to server 'KeyExchangeInitMessage': 'SSH_MSG_KEXINIT'.

SshNet.Logging Verbose: 1 : SendMessage to server 'KeyExchangeDhGroupExchangeRequest': 'SSH_MSG_KEX_DH_GEX_REQUEST'.

SshNet.Logging Verbose: 1 : ReceiveMessage from server: 'KeyExchangeDhGroupExchangeGroup': 'SSH_MSG_KEX_DH_GEX_GROUP'.

SshNet.Logging Verbose: 1 : SendMessage to server 'KeyExchangeDhGroupExchangeInit': 'SSH_MSG_KEX_DH_GEX_INIT'.

SshNet.Logging Verbose: 1 : ReceiveMessage from server: 'KeyExchangeDhGroupExchangeReply': 'SSH_MSG_KEX_DH_GEX_REPLY'.

SshNet.Logging Verbose: 1 : SendMessage to server 'NewKeysMessage': 'SSH_MSG_NEWKEYS'.

SshNet.Logging Verbose: 1 : ReceiveMessage from server: 'NewKeysMessage': 'SSH_MSG_NEWKEYS'.

SshNet.Logging Verbose: 1 : SendMessage to server 'ServiceRequestMessage': 'SSH_MSG_SERVICE_REQUEST'.

SshNet.Logging Verbose: 1 : ReceiveMessage from server: 'ServiceAcceptMessage': 'SSH_MSG_SERVICE_ACCEPT'.

SshNet.Logging Verbose: 1 : SendMessage to server 'RequestMessageNone': 'SSH_MSG_USERAUTH_REQUEST'.

SshNet.Logging Verbose: 1 : ReceiveMessage from server: 'FailureMessage': 'SSH_MSG_USERAUTH_FAILURE'.

SshNet.Logging Verbose: 1 : SendMessage to server 'RequestMessagePassword': 'SSH_MSG_USERAUTH_REQUEST'.

SshNet.Logging Verbose: 1 : ReceiveMessage from server: 'SuccessMessage': 'SSH_MSG_USERAUTH_SUCCESS'.

SshNet.Logging Verbose: 1 : SendMessage to server 'ChannelOpenMessage': 'SSH_MSG_CHANNEL_OPEN : #0'.

SshNet.Logging Verbose: 1 : ReceiveMessage from server: 'ChannelOpenConfirmationMessage': 'SSH_MSG_CHANNEL_OPEN_CONFIRMATION : #0'.

SshNet.Logging Verbose: 1 : SendMessage to server 'ChannelRequestMessage': 'SSH_MSG_CHANNEL_REQUEST : #0'.

SshNet.Logging Verbose: 1 : ReceiveMessage from server: 'ChannelWindowAdjustMessage': 'SSH_MSG_CHANNEL_WINDOW_ADJUST : #0'.

SshNet.Logging Verbose: 1 : ReceiveMessage from server: 'ChannelSuccessMessage': 'SSH_MSG_CHANNEL_SUCCESS : #0'.

SshNet.Logging Verbose: 1 : SendMessage to server 'ChannelDataMessage': 'SSH_MSG_CHANNEL_DATA : #0'.

SshNet.Logging Verbose: 1 : ReceiveMessage from server: 'ChannelDataMessage': 'SSH_MSG_CHANNEL_DATA : #0'.

SshNet.Logging Verbose: 1 : SendMessage to server 'ChannelDataMessage': 'SSH_MSG_CHANNEL_DATA : #0'.

SshNet.Logging Verbose: 1 : ReceiveMessage from server: 'ChannelDataMessage': 'SSH_MSG_CHANNEL_DATA : #0'.

SshNet.Logging Verbose: 1 : SendMessage to server 'ChannelDataMessage': 'SSH_MSG_CHANNEL_DATA : #0'.

SshNet.Logging Verbose: 1 : ReceiveMessage from server: 'ChannelDataMessage': 'SSH_MSG_CHANNEL_DATA : #0'.

SshNet.Logging Verbose: 1 : SendMessage to server 'ChannelDataMessage': 'SSH_MSG_CHANNEL_DATA : #0'.

SshNet.Logging Verbose: 1 : ReceiveMessage from server: 'ChannelDataMessage': 'SSH_MSG_CHANNEL_DATA : #0'.

SshNet.Logging Verbose: 1 : SendMessage to server 'ChannelDataMessage': 'SSH_MSG_CHANNEL_DATA : #0'.

SshNet.Logging Verbose: 1 : ReceiveMessage from server: 'ChannelDataMessage': 'SSH_MSG_CHANNEL_DATA : #0'.

SshNet.Logging Verbose: 1 : SendMessage to server 'ChannelDataMessage': 'SSH_MSG_CHANNEL_DATA : #0'.

SshNet.Logging Verbose: 1 : ReceiveMessage from server: 'ChannelDataMessage': 'SSH_MSG_CHANNEL_DATA : #0'.

SshNet.Logging Verbose: 1 : SendMessage to server 'ChannelDataMessage': 'SSH_MSG_CHANNEL_DATA : #0'.

SshNet.Logging Verbose: 1 : ReceiveMessage from server: 'ChannelDataMessage': 'SSH_MSG_CHANNEL_DATA : #0'.

SshNet.Logging Verbose: 1 : SendMessage to server 'ChannelEofMessage': 'SSH_MSG_CHANNEL_EOF : #0'.

SshNet.Logging Verbose: 1 : SendMessage to server 'ChannelCloseMessage': 'SSH_MSG_CHANNEL_CLOSE : #0'.

SshNet.Logging Verbose: 1 : SendMessage to server 'DisconnectMessage': 'SSH_MSG_DISCONNECT'.

Test method Renci.SshNet.Tests.SftpClientTests.ListDirectoryTest.Test_Sftp_ListDirectory_Empty threw exception: Renci.SshNet.Common.SshOperationTimeoutException: Session operation has timed out

    at Renci.SshNet.Session.WaitHandle(WaitHandle waitHandle) in Session.cs: line 635   at Renci.SshNet.Channels.Channel.Close() in Channel.cs: line 222   at Renci.SshNet.Sftp.SubsystemSession.Disconnect() in SubsystemSession.cs: line 95   at Renci.SshNet.SftpClient.OnDisconnecting() in SftpClient.cs: line 1318   at Renci.SshNet.BaseClient.Disconnect() in BaseClient.cs: line 124   at Renci.SshNet.Tests.SftpClientTests.ListDirectoryTest.Test_Sftp_ListDirectory_Empty() in ListDirectoryTest.cs: line 117

Any help is appreciated!


Coordinator
Dec 20, 2012 at 6:09 PM

Hi,

 

Can you please try latest source and see if you can reproduce this error?

I made several improvements in regards to disconnect, locking and exception so would like to know if this error still relevant.

 

Thanks,

Oleg

Dec 24, 2012 at 8:53 AM

Hi Oleg,

We will do so this week. I let you know about the result.

Thanks,

Christoph

Jan 7, 2013 at 6:28 AM

Hi Oleg,

We have testet your latest version. The situation has improved a lot. Out of 200 attemts 196 successed which is a great improvement. Before your latest changes the result would have been the opposite. Is this latest version of the library production ready?

Thanks,

Christoph

Coordinator
Jan 7, 2013 at 5:28 PM

Hi,

 

Thanks for testing.

If you can find out what happens with other 4 times, I would like to see if I could improve that as well, however it might be difficult to track as far as I know :(

Well, I am planning to release soon a new version which will include all latest code changes and fixes I made before I will be pooled to my previous project :(

So if you using latest source code version, feel free to use that since this is what I will use for the main release.

 

Hope it helps,

Thanks,

Oleg