I did find a way to fix the problem. The following patch is what I used:
Index:
C:/Work/ExternalProjects/Mina/sshd/sshd-core/src/main/java/org/apache/sshd/client/channel/AbstractClientChannel.java
===================================================================
---
C:/Work/ExternalProjects/Mina/sshd/sshd-core/src/main/java/org/apache/sshd/client/channel/AbstractClientChannel.java
(revision 1391504)
+++
C:/Work/ExternalProjects/Mina/sshd/sshd-core/src/main/java/org/apache/sshd/client/channel/AbstractClientChannel.java
(working copy)
@@ -92,7 +92,7 @@
} else {
openFuture.addListener(new
SshFutureListener<OpenFuture>() {
public void operationComplete(OpenFuture
future) {
- close(true);
+ close(immediately);
}
});
}
Now in the log I see:
2012-09-28 12:37:23,275 [NioProcessor-2] TRACE
o.a.s.c.session.ClientSessionImpl - Received packet #6: 5b 00 00 00 00
00 00 00 00 00 20 00 00 00 00 80 00
2012-09-28 12:37:23,275 [NioProcessor-2] DEBUG
o.a.s.c.session.ClientSessionImpl - Received packet
SSH_MSG_CHANNEL_OPEN_CONFIRMATION
2012-09-28 12:37:23,275 [NioProcessor-2] DEBUG
o.a.s.c.session.ClientSessionImpl - Received
SSH_MSG_CHANNEL_OPEN_CONFIRMATION on channel 0
2012-09-28 12:37:23,276 [NioProcessor-2] DEBUG
o.a.s.c.s.TcpipForwardSupport$ChannelForwardedTcpip - Send
SSH_MSG_CHANNEL_CLOSE on channel 0
2012-09-28 12:37:23,276 [NioProcessor-2] TRACE
o.a.s.c.session.ClientSessionImpl - Sending packet #6: 61 00 00 00 00
2012-09-28 12:37:23,277 [NioProcessor-2] TRACE
o.a.s.c.session.ClientSessionImpl - Received packet #7: 61 00 00 00 00
2012-09-28 12:37:23,277 [NioProcessor-2] DEBUG
o.a.s.c.session.ClientSessionImpl - Received packet SSH_MSG_CHANNEL_CLOSE
2012-09-28 12:37:23,277 [NioProcessor-2] DEBUG
o.a.s.c.s.TcpipForwardSupport$ChannelForwardedTcpip - Received
SSH_MSG_CHANNEL_CLOSE on channel 0
If the change makes sense to you, I can create a JIRA issue for it and
post the patch to it.
Kevin
On September-28-12 12:13:14 PM, Kevin Winchester wrote:
On 28/09/2012 9:13 AM, Guillaume Nodet wrote:
If you want to be fully asynchronous, you need to use listeners.
sshClient.connect( host, port ).addListener(
new SshFutureListener<ConnectFuture> {
public void operationComplete( ConnectFuture connect ) {
ClientSession session = connect.getSession();
// start authentication process ...
}
});
Yes, that is the approach I ended up taking. I also created SSHD-190
to reflect the fact that I could not add a SessionListener to the
ClientSession instance.
I have now seen the problem again that I mentioned in my earlier email
about getting disconnected. The sequence is this:
* Connect to server
* Create local port forwarding tunnel
* Test the local port forwarding tunnel by connecting and immediately
disconnecting from the local port, which creates and then destroys
channel 0
* Wait exactly 1 minute (some kind of timeout?)
* Server determines that the connection for its channel 0 is no longer
present and it sends EOF, which causes the client to disconnect since
it no longer has a channel zero
Here is the client log, which I think shows the problem:
2012-09-28 11:29:55,084 [NioProcessor-2] TRACE
o.a.s.c.session.ClientSessionImpl - Received packet #5: 34
2012-09-28 11:29:55,084 [NioProcessor-2] DEBUG
o.a.s.c.session.ClientSessionImpl - Received packet
SSH_MSG_USERAUTH_SUCCESS
2012-09-28 11:29:55,085 [NioProcessor-2] INFO
o.a.s.client.auth.UserAuthPassword - Received SSH_MSG_USERAUTH_SUCCESS
2012-09-28 11:29:55,115 [NioProcessor-13] INFO
o.a.s.c.s.TcpipForwardSupport$ChannelForwardedTcpip - Send
SSH_MSG_CHANNEL_OPEN on channel 0
2012-09-28 11:29:55,116 [NioProcessor-13] TRACE
o.a.s.c.session.ClientSessionImpl - Sending packet #5: 5a 00 00 00 0c
64 69 72 65 63 74 2d 74 63 70 69 70 00 00 00 00 00 20 00 00 00 00 80
00 00 00 00 0d 31 39 39 2e 35 39 2e 31 33 33 2e 37 37 00 00 0d 3d 00
00 00 09 31 32 37 2e 30 2e 30 2e 31 00 00 c3 6d
2012-09-28 11:29:55,117 [NioProcessor-13] DEBUG
o.a.m.f.e.OrderedThreadPoolExecutor - Adding event SESSION_OPENED to
session 3
Queue : [SESSION_OPENED, ]
2012-09-28 11:29:55,118 [pool-7-thread-1] DEBUG
o.a.m.core.filterchain.IoFilterEvent - Firing a SESSION_OPENED event
for session 3
2012-09-28 11:29:55,118 [NioProcessor-13] DEBUG
o.a.m.f.e.OrderedThreadPoolExecutor - Adding event SESSION_CLOSED to
session 3
Queue : [SESSION_CLOSED, ]
2012-09-28 11:29:55,118 [pool-7-thread-1] DEBUG
o.a.m.core.filterchain.IoFilterEvent - Event SESSION_OPENED has been
fired for session 3
2012-09-28 11:29:55,119 [pool-7-thread-1] DEBUG
o.a.m.core.filterchain.IoFilterEvent - Firing a SESSION_CLOSED event
for session 3
2012-09-28 11:29:55,119 [pool-7-thread-1] DEBUG
o.a.m.core.filterchain.IoFilterEvent - Event SESSION_CLOSED has been
fired for session 3
2012-09-28 11:29:55,134 [NioProcessor-2] TRACE
o.a.s.c.session.ClientSessionImpl - Received packet #6: 5b 00 00 00 00
00 00 00 00 00 20 00 00 00 00 80 00
2012-09-28 11:29:55,134 [NioProcessor-2] DEBUG
o.a.s.c.session.ClientSessionImpl - Received packet
SSH_MSG_CHANNEL_OPEN_CONFIRMATION
2012-09-28 11:29:55,134 [NioProcessor-2] DEBUG
o.a.s.c.session.ClientSessionImpl - Received
SSH_MSG_CHANNEL_OPEN_CONFIRMATION on channel 0
2012-09-28 11:29:55,134 [NioProcessor-2] DEBUG
o.a.s.c.s.TcpipForwardSupport$ChannelForwardedTcpip - Closing channel
0 immediately
*** Preceisely one minute later: ***
2012-09-28 11:30:55,134 [NioProcessor-2] TRACE
o.a.s.c.session.ClientSessionImpl - Received packet #105: 60 00 00 00 00
2012-09-28 11:30:55,134 [NioProcessor-2] DEBUG
o.a.s.c.session.ClientSessionImpl - Received packet SSH_MSG_CHANNEL_EOF
2012-09-28 11:30:55,135 [NioProcessor-2] WARN
o.a.s.c.session.ClientSessionImpl - Exception caught
org.apache.sshd.common.SshException: Received SSH_MSG_CHANNEL_EOF on
unknown channel 0
at
org.apache.sshd.common.session.AbstractSession.getChannel(AbstractSession.java:1084)
~[sshd-core-0.9.0-SNAPSHOT.jar:0.9.0-SNAPSHOT]
at
org.apache.sshd.common.session.AbstractSession.channelEof(AbstractSession.java:1024)
~[sshd-core-0.9.0-SNAPSHOT.jar:0.9.0-SNAPSHOT]
at
org.apache.sshd.client.session.ClientSessionImpl.doHandleMessage(ClientSessionImpl.java:434)
~[sshd-core-0.9.0-SNAPSHOT.jar:0.9.0-SNAPSHOT]
at
org.apache.sshd.client.session.ClientSessionImpl.handleMessage(ClientSessionImpl.java:307)
~[sshd-core-0.9.0-SNAPSHOT.jar:0.9.0-SNAPSHOT]
at
org.apache.sshd.common.session.AbstractSession.decode(AbstractSession.java:566)
~[sshd-core-0.9.0-SNAPSHOT.jar:0.9.0-SNAPSHOT]
at
org.apache.sshd.common.session.AbstractSession.messageReceived(AbstractSession.java:236)
~[sshd-core-0.9.0-SNAPSHOT.jar:0.9.0-SNAPSHOT]
at
org.apache.sshd.common.AbstractSessionIoHandler.messageReceived(AbstractSessionIoHandler.java:58)
~[sshd-core-0.9.0-SNAPSHOT.jar:0.9.0-SNAPSHOT]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.messageReceived(DefaultIoFilterChain.java:716)
~[mina-core-2.0.5.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:434)
[mina-core-2.0.5.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoFilterChain.java:46)
[mina-core-2.0.5.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:796)
[mina-core-2.0.5.jar:na]
at
org.apache.mina.core.filterchain.IoFilterAdapter.messageReceived(IoFilterAdapter.java:119)
[mina-core-2.0.5.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:434)
[mina-core-2.0.5.jar:na]
at
org.apache.mina.core.filterchain.DefaultIoFilterChain.fireMessageReceived(DefaultIoFilterChain.java:426)
[mina-core-2.0.5.jar:na]
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:697)
[mina-core-2.0.5.jar:na]
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:651)
[mina-core-2.0.5.jar:na]
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:640)
[mina-core-2.0.5.jar:na]
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.access$600(AbstractPollingIoProcessor.java:67)
[mina-core-2.0.5.jar:na]
at
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1111)
[mina-core-2.0.5.jar:na]
at
org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
[mina-core-2.0.5.jar:na]
at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown
Source) [na:1.7.0_07]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown
Source) [na:1.7.0_07]
at java.lang.Thread.run(Unknown Source) [na:1.7.0_07]
2012-09-28 11:30:55,135 [NioProcessor-2] DEBUG
o.a.s.c.session.ClientSessionImpl - Closing session
2012-09-28 11:30:55,135 [NioProcessor-2] DEBUG
o.a.s.c.session.ClientSessionImpl - Closing IoSession
2012-09-28 11:30:55,136 [NioProcessor-2] DEBUG
o.a.s.c.session.ClientSessionImpl - IoSession closed
2012-09-28 11:30:55,136 [NioProcessor-2] INFO
o.a.s.c.session.ClientSessionImpl - Session
user@localhost/127.0.0.1:9022 closed
It appears that the IO Session is being closed for the test connection
before the SSH_MSG_CHANNEL_OPEN_CONFIRMATION is received. Thus when
the SSH_MSG_CHANNEL_OPEN_CONFIRMATION is finally received, the channel
has already decided to close, and it does so without telling the server.
This might possibly happen in the PortForwardingTest case as well, but
there the client/server are likely torn down before the 1 minute
timeout expires that would cause the server to realize that the client
channel connection is gone.
I am going to see if I can modify the client code to ensure that it
does tell the server about closing the channel in this case. I'll let
you know if it helps.
Kevin
