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
