SshOperationTimeoutException disposing stream for connection that was already terminated by server

[JasonQG]

Since upgrading to 2016.1.0, I'm getting the below exception. Right before the stream was disposed, a command was sent to reboot the server, thus terminating the SSH connection on the server side. The same code worked with 2016.0.0.

System.AggregateException: One or more errors occurred. ---> Renci.SshNet.Common.SshOperationTimeoutException: Session operation has timed out
   at Renci.SshNet.Session.WaitOnHandle(WaitHandle waitHandle, TimeSpan timeout)
   at Renci.SshNet.Session.Renci.SshNet.ISession.WaitOnHandle(WaitHandle waitHandle)
   at Renci.SshNet.Channels.Channel.Close()
   at Renci.SshNet.Channels.ChannelSession.Close()
   at Renci.SshNet.Channels.Channel.Dispose(Boolean disposing)
   at Renci.SshNet.Channels.ClientChannel.Dispose(Boolean disposing)
   at Renci.SshNet.Channels.ChannelSession.Dispose(Boolean disposing)
   at Renci.SshNet.Channels.Channel.Dispose()
   at Renci.SshNet.ShellStream.Dispose(Boolean disposing)
   at System.IO.Stream.Close()
   at System.IO.Stream.Dispose()

[drieseng]

Are you sure you are using 2016.1.0 (RTM), and not one of the betas?
Can you reproduce this issue consistently?

I fixed an issue in Channel in beta4, and improved robustness even more recently (currently in the develop branch, and will be in the upcoming 2017.0.0-beta1 release).
I cannot reproduce this issue using either 2016.0.0-beta4, 2016.0.0 or the develop branch.

[JasonQG]

I started with beta 5, and then I upgraded to the RTM and saw it there too. There must be something else going on with our setup if you're not seeing it, but I'm not sure what at this time. When I can find some time, I'll try to look into it further. For now, I downgraded to avoid the problem.

[drieseng]

Would it be possible for you to build SSH.NET from source (the develop branch)?
If you can still reproduce it from the develop branch, I can add extra tracing to allow me to pinpoint the cause.

I'd really like to fix this issue.

[JasonQG]

Thanks for being willing to help out with this. I just downloaded the latest source and was still able to reproduce it. Now what?

[drieseng]

I suppose it's because the (SSH) server does not send a SSH_MSG_CHANNEL_CLOSE message before rebooting. What SSH server are you testing against? See this page for instructions on how you can obtain that info.

In previous versions of SSH.NET we were not waiting for the SSH_MSG_CHANNEL_CLOSE message. That explains why you only see this issue with 2016.1.0.

I'll add extra tracing to allow us to get more information, and let you know when I've committed these changes.

[JasonQG]

SSH-2.0-dropbear_2012.55

[drieseng]

@JasonQG I cannot reproduce this issue using dropbear version 2013.60. Can you share the minimal code you need to reproduce this issue? Do you get the error consistently, or once every x number of times?

[JasonQG]

It happens consistently. There's nothing particularly special about the code. Just a command that resets and then a Dispose(). I suppose maybe the way the system is resetting isn't giving dropbear a chance to send the channel close message maybe?

[drieseng]

Yes, that was indeed was I was thinking. Is it ok if I just add some Console.WriteLine(...) tracing (which end up in standard output) to the develop branch to allow us to confirm this?

[JasonQG]

Of course. Please go ahead

[drieseng]

I've added a cwl-tracing branch that - as the name says - adds some Console.WriteLine(...) tracing to allow us to troubleshoot this issue.

When run against OpenSSH_6.6.1p1, I get the following output:

[1] Disposing ShellStream.
[1] Disposing channel from ShellStream.Dispose(bool).
[1] In Close() 0/0.
[1] Sending SSH_MSG_CHANNEL_EOF for channel 0/0.
[1] Sent SSH_MSG_CHANNEL_EOF for channel 0/0.
[1] Sending SSH_MSG_CHANNEL_CLOSE for channel 0/0.
[1] Sent SSH_MSG_CHANNEL_CLOSE for channel 0/0.
[1] Waiting for server to close channel 0/0.
[5] SSH_MSG_CHANNEL_CLOSE received from server 0/0.
[5] Closing channel after receiving SSH_MSG_CHANNEL_CLOSE from server 0/0.
[5] In Close() 0/0.
[1] Finished waiting for server to close channel 0/0.
[1] Disposed channel from ShellStream.Dispose(bool).

Please provide your exact result.

[JasonQG]

This is what I got:

[30] Disposing ShellStream.
[30] Disposing channel from ShellStream.Dispose(bool).
[30] In Close() 0/0.
[30] Sending SSH_MSG_CHANNEL_EOF for channel 0/0.
[30] Sent SSH_MSG_CHANNEL_EOF for channel 0/0.
[30] Sending SSH_MSG_CHANNEL_CLOSE for channel 0/0.
[30] Sent SSH_MSG_CHANNEL_CLOSE for channel 0/0.
[30] Waiting for server to close channel 0/0.
Exception thrown: 'Renci.SshNet.Common.SshOperationTimeoutException' in Renci.SshNet.dll
SshNet.Logging Verbose: 30 : Disconnecting client.
SshNet.Logging Verbose: 30 : [E69D2DFDD3B2FD62AF553A49F1ADB6D81606A244] Disposing session.
SshNet.Logging Verbose: 30 : [E69D2DFDD3B2FD62AF553A49F1ADB6D81606A244] Disconnecting session.
SshNet.Logging Verbose: 30 : [E69D2DFDD3B2FD62AF553A49F1ADB6D81606A244] Sending message 'DisconnectMessage' to server: 'SSH_MSG_DISCONNECT'.
SshNet.Logging Verbose: 30 : [E69D2DFDD3B2FD62AF553A49F1ADB6D81606A244] Shutting down socket.
SshNet.Logging Verbose: 30 : [E69D2DFDD3B2FD62AF553A49F1ADB6D81606A244] Disposing socket.
SshNet.Logging Verbose: 30 : [E69D2DFDD3B2FD62AF553A49F1ADB6D81606A244] Disposed socket.
SshNet.Logging Verbose: 22 : [E69D2DFDD3B2FD62AF553A49F1ADB6D81606A244] Raised exception: Renci.SshNet.Common.SshConnectionException: An established connection was aborted by the server.
[30] Exception waiting for server to close channel 0/0: Renci.SshNet.Common.SshOperationTimeoutException: Session operation has timed out
at Renci.SshNet.Session.WaitOnHandle(WaitHandle waitHandle, TimeSpan timeout) in C:\jasong\ws_jasong\sit5\cur\Libraries\3rdParty\SshNet\Session.cs:line 837
at Renci.SshNet.Session.Renci.SshNet.ISession.WaitOnHandle(WaitHandle waitHandle) in C:\jasong\ws_jasong\sit5\cur\Libraries\3rdParty\SshNet\Session.cs:line 763
at Renci.SshNet.Channels.Channel.WaitOnHandle(WaitHandle waitHandle) in C:\jasong\ws_jasong\sit5\cur\Libraries\3rdParty\SshNet\Channels\Channel.cs:line 522
at Renci.SshNet.Channels.Channel.Close() in C:\jasong\ws_jasong\sit5\cur\Libraries\3rdParty\SshNet\Channels\Channel.cs:line 574.
[30] Disposed channel from ShellStream.Dispose(bool).
Exception thrown: 'System.Threading.Tasks.TaskCanceledException' in mscorlib.dll
SshNet.Logging Verbose: 45 : [54790C418B85BBBB790989066521950F2AEB82CE] Sending message 'ChannelEofMessage' to server: 'SSH_MSG_CHANNEL_EOF : #0'.
SshNet.Logging Verbose: 45 : [54790C418B85BBBB790989066521950F2AEB82CE] Sending message 'ChannelCloseMessage' to server: 'SSH_MSG_CHANNEL_CLOSE : #0'.
[45] Disposing ShellStream.
[45] Disposing channel from ShellStream.Dispose(bool).
[45] In Close() 0/0.
[45] Sending SSH_MSG_CHANNEL_EOF for channel 0/0.
[45] Sent SSH_MSG_CHANNEL_EOF for channel 0/0.
[45] Sending SSH_MSG_CHANNEL_CLOSE for channel 0/0.
[45] Sent SSH_MSG_CHANNEL_CLOSE for channel 0/0.
[45] Waiting for server to close channel 0/0.
Exception thrown: 'System.Net.Sockets.SocketException' in System.dll
Exception thrown: 'System.Net.Sockets.SocketException' in Renci.SshNet.dll
SshNet.Logging Verbose: 23 : [54790C418B85BBBB790989066521950F2AEB82CE] Raised exception: Renci.SshNet.Common.SshConnectionException: An existing connection was forcibly closed by the remote host ---> System.Net.Sockets.SocketException: An existing connection was forcibly closed by the remote host
at System.Net.Sockets.Socket.Receive(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags)
at Renci.SshNet.Abstractions.SocketAbstraction.Read(Socket socket, Byte[] buffer, Int32 offset, Int32 size, TimeSpan timeout) in C:\jasong\ws_jasong\sit5\cur\Libraries\3rdParty\SshNet\Abstractions\SocketAbstraction.cs:line 328
at Renci.SshNet.Session.TrySocketRead(Byte[] buffer, Int32 offset, Int32 length) in C:\jasong\ws_jasong\sit5\cur\Libraries\3rdParty\SshNet\Session.cs:line 1744
at Renci.SshNet.Session.ReceiveMessage() in C:\jasong\ws_jasong\sit5\cur\Libraries\3rdParty\SshNet\Session.cs:line 1010
at Renci.SshNet.Session.MessageListener() in C:\jasong\ws_jasong\sit5\cur\Libraries\3rdParty\SshNet\Session.cs:line 1892
--- End of inner exception stack trace ---
Exception thrown: 'Renci.SshNet.Common.SshConnectionException' in Renci.SshNet.dll
SshNet.Logging Verbose: 23 : [54790C418B85BBBB790989066521950F2AEB82CE] Disconnecting after exception: Renci.SshNet.Common.SshConnectionException: An existing connection was forcibly closed by the remote host ---> System.Net.Sockets.SocketException: An existing connection was forcibly closed by the remote host
at System.Net.Sockets.Socket.Receive(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags)
at Renci.SshNet.Abstractions.SocketAbstraction.Read(Socket socket, Byte[] buffer, Int32 offset, Int32 size, TimeSpan timeout) in C:\jasong\ws_jasong\sit5\cur\Libraries\3rdParty\SshNet\Abstractions\SocketAbstraction.cs:line 328
at Renci.SshNet.Session.TrySocketRead(Byte[] buffer, Int32 offset, Int32 length) in C:\jasong\ws_jasong\sit5\cur\Libraries\3rdParty\SshNet\Session.cs:line 1744
at Renci.SshNet.Session.ReceiveMessage() in C:\jasong\ws_jasong\sit5\cur\Libraries\3rdParty\SshNet\Session.cs:line 1010
at Renci.SshNet.Session.MessageListener() in C:\jasong\ws_jasong\sit5\cur\Libraries\3rdParty\SshNet\Session.cs:line 1892
--- End of inner exception stack trace ---
at Renci.SshNet.Session.WaitOnHandle(WaitHandle waitHandle, TimeSpan timeout) in C:\jasong\ws_jasong\sit5\cur\Libraries\3rdParty\SshNet\Session.cs:line 825
at Renci.SshNet.Session.Renci.SshNet.ISession.WaitOnHandle(WaitHandle waitHandle) in C:\jasong\ws_jasong\sit5\cur\Libraries\3rdParty\SshNet\Session.cs:line 763
at Renci.SshNet.Channels.Channel.WaitOnHandle(WaitHandle waitHandle) in C:\jasong\ws_jasong\sit5\cur\Libraries\3rdParty\SshNet\Channels\Channel.cs:line 522
at Renci.SshNet.Channels.Channel.Close() in C:\jasong\ws_jasong\sit5\cur\Libraries\3rdParty\SshNet\Channels\Channel.cs:line 574
SshNet.Logging Verbose: 23 : [54790C418B85BBBB790989066521950F2AEB82CE] Disposing socket.
SshNet.Logging Verbose: 23 : [54790C418B85BBBB790989066521950F2AEB82CE] Disposed socket.
[45] SSH connection exception waiting for server to close channel 0/0: Renci.SshNet.Common.SshConnectionException: An existing connection was forcibly closed by the remote host ---> System.Net.Sockets.SocketException: An existing connection was forcibly closed by the remote host
at System.Net.Sockets.Socket.Receive(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags)
at Renci.SshNet.Abstractions.SocketAbstraction.Read(Socket socket, Byte[] buffer, Int32 offset, Int32 size, TimeSpan timeout) in C:\jasong\ws_jasong\sit5\cur\Libraries\3rdParty\SshNet\Abstractions\SocketAbstraction.cs:line 328
at Renci.SshNet.Session.TrySocketRead(Byte[] buffer, Int32 offset, Int32 length) in C:\jasong\ws_jasong\sit5\cur\Libraries\3rdParty\SshNet\Session.cs:line 1744
at Renci.SshNet.Session.ReceiveMessage() in C:\jasong\ws_jasong\sit5\cur\Libraries\3rdParty\SshNet\Session.cs:line 1010
at Renci.SshNet.Session.MessageListener() in C:\jasong\ws_jasong\sit5\cur\Libraries\3rdParty\SshNet\Session.cs:lSshNet.Logging Verbose: 45 : Disconnecting client.
SshNet.Logging Verbose: 45 : [54790C418B85BBBB790989066521950F2AEB82CE] Disposing session.
SshNet.Logging Verbose: 45 : [54790C418B85BBBB790989066521950F2AEB82CE] Disconnecting session.
ine 1892
--- End of inner exception stack trace ---
at Renci.SshNet.Session.WaitOnHandle(WaitHandle waitHandle, TimeSpan timeout) in C:\jasong\ws_jasong\sit5\cur\Libraries\3rdParty\SshNet\Session.cs:line 825
at Renci.SshNet.Session.Renci.SshNet.ISession.WaitOnHandle(WaitHandle waitHandle) in C:\jasong\ws_jasong\sit5\cur\Libraries\3rdParty\SshNet\Session.cs:line 763
at Renci.SshNet.Channels.Channel.WaitOnHandle(WaitHandle waitHandle) in C:\jasong\ws_jasong\sit5\cur\Libraries\3rdParty\SshNet\Channels\Channel.cs:line 522
at Renci.SshNet.Channels.Channel.Close() in C:\jasong\ws_jasong\sit5\cur\Libraries\3rdParty\SshNet\Channels\Channel.cs:line 574.
[45] Disposed channel from ShellStream.Dispose(bool).

[drieseng]

@JasonQG This confirms that the server does not always send a SSH_MSG_CHANNEL_CLOSE message before the socket is closed.

I'm adding a ChannelCloseTimeout property on ConnectionInfo that allows you to control how long you want to wait for the server to send a SSH_MSG_CHANNEL_CLOSE. The default value is 1 second.