SSHJ interaction with Apache SSHD (causing [PROTOCOL_ERROR] Received CHANNEL_SUCCESS on unknown channel #0

[Martin Lichtin]

Hi

Can someone help me understand what is happening here?
I have an integration test case with Apache SSHD as the server and SSHJ as the client.
The authentication works fine, but then a command execution (simulating the command response on the server side) fails with

ConnectionException: [PROTOCOL_ERROR] Received CHANNEL_SUCCESS on unknown channel #0

The full output is:

2014-12-22 15:07:22,153 []-nio2-thread-1] DEBUG org.apache.sshd.server.session.ServerUserAuthService          170 - Authentication succeeded
2014-12-22 15:07:22,153 []-nio2-thread-1] TRACE org.apache.sshd.common.session.AbstractSession                597 - Sending packet #5: 34
2014-12-22 15:07:22,153 []-nio2-thread-1] DEBUG org.apache.sshd.common.io.nio2.Nio2Session                    105 - Writing 52 bytes
2014-12-22 15:07:22,169 []-nio2-thread-1] INFO  org.apache.sshd.server.session.ServerUserAuthService          207 - Session mli@/127.0.0.1:63822 authenticated
2014-12-22 15:07:22,169 [reader         ] TRACE net.schmizz.sshj.transport.Decoder                            105 - Received packet #5: 34
2014-12-22 15:07:22,169 [reader         ] TRACE net.schmizz.sshj.transport.TransportImpl                      452 - Received packet USERAUTH_SUCCESS
2014-12-22 15:07:22,169 [reader         ] DEBUG net.schmizz.concurrent.Promise                                 78 - Setting <<authenticated>> to `true`
2014-12-22 15:07:22,169 []-nio2-thread-3] DEBUG org.apache.sshd.common.io.nio2.Nio2Session$2                  223 - Finished writing
2014-12-22 15:07:22,169 [oller-127.0.0.1] DEBUG net.schmizz.sshj.userauth.UserAuthImpl                         72 - `password` auth successful
2014-12-22 15:07:22,169 [oller-127.0.0.1] DEBUG net.schmizz.sshj.transport.TransportImpl                      283 - Setting active service to ssh-connection
2014-12-22 15:07:22,200 [oller-127.0.0.1] DEBUG net.schmizz.sshj.connection.ConnectionImpl                     71 - Attaching `session` channel (#0)
2014-12-22 15:07:22,200 [oller-127.0.0.1] TRACE net.schmizz.sshj.transport.Encoder                             80 - Encoding packet #5: 5a 00 00 00 07 73 65 73 73 69 6f 6e 00 00 00 00 00 20 00 00 00 00 80 00
2014-12-22 15:07:22,200 [oller-127.0.0.1] DEBUG net.schmizz.concurrent.Promise                                164 - Awaiting <<chan#0 / open>>
2014-12-22 15:07:22,200 []-nio2-thread-1] DEBUG org.apache.sshd.common.io.nio2.Nio2Session$1                  177 - Read 68 bytes
2014-12-22 15:07:22,200 []-nio2-thread-1] TRACE org.apache.sshd.common.session.AbstractSession                725 - Received packet #7: 5a 00 00 00 07 73 65 73 73 69 6f 6e 00 00 00 00 00 20 00 00 00 00 80 00
2014-12-22 15:07:22,200 []-nio2-thread-1] DEBUG org.apache.sshd.common.session.AbstractConnectionService      299 - Received SSH_MSG_CHANNEL_OPEN session
2014-12-22 15:07:22,200 []-nio2-thread-1] TRACE org.apache.sshd.common.session.AbstractSession                597 - Sending packet #6: 5b 00 00 00 00 00 00 00 00 00 20 00 00 00 00 80 00
2014-12-22 15:07:22,200 []-nio2-thread-1] DEBUG org.apache.sshd.common.io.nio2.Nio2Session                    105 - Writing 68 bytes
2014-12-22 15:07:22,200 [reader         ] TRACE net.schmizz.sshj.transport.Decoder                            105 - Received packet #6: 5b 00 00 00 00 00 00 00 00 00 20 00 00 00 00 80 00
2014-12-22 15:07:22,200 [reader         ] TRACE net.schmizz.sshj.transport.TransportImpl                      452 - Received packet CHANNEL_OPEN_CONFIRMATION
2014-12-22 15:07:22,216 [reader         ] DEBUG net.schmizz.sshj.connection.channel.AbstractChannel           102 - Initialized - < session channel: id=0, recipient=0, localWin=[winSize=2097152], remoteWin=[winSize=2097152] >
2014-12-22 15:07:22,216 [reader         ] DEBUG net.schmizz.concurrent.Promise                                 78 - Setting <<chan#0 / open>> to `SOME`
2014-12-22 15:07:22,216 []-nio2-thread-1] DEBUG org.apache.sshd.common.io.nio2.Nio2Session$2                  223 - Finished writing
2014-12-22 15:07:22,216 [oller-127.0.0.1] INFO  net.schmizz.sshj.connection.channel.direct.SessionChannel     100 - Will request to exec `ps`
2014-12-22 15:07:22,216 [oller-127.0.0.1] DEBUG net.schmizz.sshj.connection.channel.AbstractChannel           353 - Sending channel request for `exec`
2014-12-22 15:07:22,216 [oller-127.0.0.1] TRACE net.schmizz.sshj.transport.Encoder                             80 - Encoding packet #6: 62 00 00 00 00 00 00 00 04 65 78 65 63 01 00 00 00 02 70 73
2014-12-22 15:07:22,216 [oller-127.0.0.1] DEBUG net.schmizz.concurrent.Promise                                164 - Awaiting <<chan#0 / chanreq for exec>>
2014-12-22 15:07:22,216 []-nio2-thread-2] DEBUG org.apache.sshd.common.io.nio2.Nio2Session$1                  177 - Read 68 bytes
2014-12-22 15:07:22,216 []-nio2-thread-2] TRACE org.apache.sshd.common.session.AbstractSession                725 - Received packet #8: 62 00 00 00 00 00 00 00 04 65 78 65 63 01 00 00 00 02 70 73
2014-12-22 15:07:22,216 []-nio2-thread-2] DEBUG org.apache.sshd.common.channel.AbstractChannel                 92 - Received SSH_MSG_CHANNEL_REQUEST exec on channel ChannelSession[id=0, recipient=0] (wantReply true)
2014-12-22 15:07:22,216 []-nio2-thread-2] TRACE org.apache.sshd.common.util.LoggingFilterOutputStream          53 - OUT: 70 73 2d 6f 75 74 70 75 74
2014-12-22 15:07:22,216 []-nio2-thread-2] TRACE org.apache.sshd.common.channel.Window                         138 - Consume server remote window by 9 down to 2097143
2014-12-22 15:07:22,216 []-nio2-thread-2] DEBUG org.apache.sshd.common.channel.ChannelOutputStream            131 - Send SSH_MSG_CHANNEL_DATA on channel 0
2014-12-22 15:07:22,216 []-nio2-thread-2] TRACE org.apache.sshd.common.session.AbstractSession                597 - Sending packet #7: 5e 00 00 00 00 00 00 00 09 70 73 2d 6f 75 74 70 75 74
2014-12-22 15:07:22,216 []-nio2-thread-2] DEBUG org.apache.sshd.common.io.nio2.Nio2Session                    105 - Writing 68 bytes
2014-12-22 15:07:22,216 []-nio2-thread-2] DEBUG org.apache.sshd.common.channel.AbstractChannel                259 - Send SSH_MSG_CHANNEL_EOF on channel ChannelSession[id=0, recipient=0]
2014-12-22 15:07:22,216 [reader         ] TRACE net.schmizz.sshj.transport.Decoder                            105 - Received packet #7: 5e 00 00 00 00 00 00 00 09 70 73 2d 6f 75 74 70 75 74
2014-12-22 15:07:22,216 []-nio2-thread-2] TRACE org.apache.sshd.common.session.AbstractSession                597 - Sending packet #8: 60 00 00 00 00
2014-12-22 15:07:22,216 [reader         ] TRACE net.schmizz.sshj.transport.TransportImpl                      452 - Received packet CHANNEL_DATA
2014-12-22 15:07:22,216 []-nio2-thread-2] DEBUG org.apache.sshd.common.io.nio2.Nio2Session                    105 - Writing 52 bytes
2014-12-22 15:07:22,216 [reader         ] TRACE net.schmizz.sshj.connection.channel.AbstractChannel           346 - IN #0: 70 73 2d 6f 75 74 70 75 74
2014-12-22 15:07:22,216 [reader         ] DEBUG net.schmizz.sshj.connection.channel.Window                     60 - Consuming by 9 down to 2097143
2014-12-22 15:07:22,216 []-nio2-thread-2] DEBUG org.apache.sshd.server.channel.AbstractServerChannel           62 - Send SSH_MSG_CHANNEL_REQUEST exit-status on channel 0
2014-12-22 15:07:22,231 []-nio2-thread-2] TRACE org.apache.sshd.common.session.AbstractSession                597 - Sending packet #9: 62 00 00 00 00 00 00 00 0b 65 78 69 74 2d 73 74 61 74 75 73 00 00 00 00 01
2014-12-22 15:07:22,231 []-nio2-thread-2] DEBUG org.apache.sshd.common.io.nio2.Nio2Session                    105 - Writing 68 bytes
2014-12-22 15:07:22,231 []-nio2-thread-2] DEBUG org.apache.sshd.common.util.CloseableUtils$AbstractCloseable  357 - Closing ChannelSession[id=0, recipient=0] gracefully
2014-12-22 15:07:22,231 []-nio2-thread-2] DEBUG org.apache.sshd.common.channel.AbstractChannel$1              160 - Send SSH_MSG_CHANNEL_CLOSE on channel ChannelSession[id=0, recipient=0]
2014-12-22 15:07:22,231 []-nio2-thread-2] TRACE org.apache.sshd.common.session.AbstractSession                597 - Sending packet #10: 61 00 00 00 00
2014-12-22 15:07:22,231 []-nio2-thread-2] DEBUG org.apache.sshd.common.io.nio2.Nio2Session                    105 - Writing 52 bytes
2014-12-22 15:07:22,231 []-nio2-thread-2] TRACE org.apache.sshd.common.session.AbstractSession                597 - Sending packet #11: 63 00 00 00 00
2014-12-22 15:07:22,231 []-nio2-thread-2] DEBUG org.apache.sshd.common.io.nio2.Nio2Session                    105 - Writing 52 bytes
2014-12-22 15:07:22,231 []-nio2-thread-1] DEBUG org.apache.sshd.common.io.nio2.Nio2Session$2                  223 - Finished writing
2014-12-22 15:07:22,231 [reader         ] TRACE net.schmizz.sshj.transport.Decoder                            105 - Received packet #8: 60 00 00 00 00
2014-12-22 15:07:22,231 [reader         ] TRACE net.schmizz.sshj.transport.TransportImpl                      452 - Received packet CHANNEL_EOF
2014-12-22 15:07:22,231 [reader         ] DEBUG net.schmizz.sshj.connection.channel.AbstractChannel           389 - Got EOF
2014-12-22 15:07:22,231 []-nio2-thread-1] DEBUG org.apache.sshd.common.io.nio2.Nio2Session$2                  223 - Finished writing
2014-12-22 15:07:22,231 [reader         ] TRACE net.schmizz.sshj.transport.Decoder                            105 - Received packet #9: 62 00 00 00 00 00 00 00 0b 65 78 69 74 2d 73 74 61 74 75 73 00 00 00 00 01
2014-12-22 15:07:22,231 [reader         ] TRACE net.schmizz.sshj.transport.TransportImpl                      452 - Received packet CHANNEL_REQUEST
2014-12-22 15:07:22,231 [reader         ] DEBUG net.schmizz.sshj.connection.channel.AbstractChannel           295 - Got chan request for `exit-status`
2014-12-22 15:07:22,231 []-nio2-thread-1] DEBUG org.apache.sshd.common.io.nio2.Nio2Session$2                  223 - Finished writing
2014-12-22 15:07:22,231 [reader         ] TRACE net.schmizz.sshj.transport.Decoder                            105 - Received packet #10: 61 00 00 00 00
2014-12-22 15:07:22,231 [reader         ] TRACE net.schmizz.sshj.transport.TransportImpl                      452 - Received packet CHANNEL_CLOSE
2014-12-22 15:07:22,231 [reader         ] DEBUG net.schmizz.sshj.connection.channel.AbstractChannel           200 - Got close
2014-12-22 15:07:22,231 [reader         ] DEBUG net.schmizz.sshj.connection.channel.AbstractChannel           267 - Sending close
2014-12-22 15:07:22,231 [reader         ] TRACE net.schmizz.sshj.transport.Encoder                             80 - Encoding packet #7: 61 00 00 00 00
2014-12-22 15:07:22,231 [reader         ] DEBUG net.schmizz.sshj.connection.ConnectionImpl                     87 - Forgetting `session` channel (#0)
2014-12-22 15:07:22,231 [reader         ] DEBUG net.schmizz.concurrent.Promise                                 78 - Setting <<chan#0 / close>> to `SOME`
2014-12-22 15:07:22,231 []-nio2-thread-1] DEBUG org.apache.sshd.common.io.nio2.Nio2Session$2                  223 - Finished writing
2014-12-22 15:07:22,231 []-nio2-thread-1] DEBUG org.apache.sshd.common.channel.AbstractChannel$1$1            167 - Message SSH_MSG_CHANNEL_CLOSE written on channel ChannelSession[id=0, recipient=0]
2014-12-22 15:07:22,231 [reader         ] TRACE net.schmizz.sshj.transport.Decoder                            105 - Received packet #11: 63 00 00 00 00
2014-12-22 15:07:22,231 [reader         ] TRACE net.schmizz.sshj.transport.TransportImpl                      452 - Received packet CHANNEL_SUCCESS
2014-12-22 15:07:22,231 [reader         ] ERROR net.schmizz.sshj.transport.TransportImpl                      555 - Dying because - {}
net.schmizz.sshj.connection.ConnectionException: [PROTOCOL_ERROR] Received CHANNEL_SUCCESS on unknown channel #0
    at net.schmizz.sshj.connection.ConnectionImpl.getChannel(ConnectionImpl.java:117)
    at net.schmizz.sshj.connection.ConnectionImpl.handle(ConnectionImpl.java:128)
    at net.schmizz.sshj.transport.TransportImpl.handle(TransportImpl.java:455)
    at net.schmizz.sshj.transport.Decoder.decode(Decoder.java:107)
    at net.schmizz.sshj.transport.Decoder.received(Decoder.java:175)
    at net.schmizz.sshj.transport.Reader.run(Reader.java:61)
2014-12-22 15:07:22,231 [reader         ] INFO  net.schmizz.sshj.transport.TransportImpl$1                     73 - Disconnected - PROTOCOL_ERROR
2014-12-22 15:07:22,231 []-nio2-thread-3] DEBUG org.apache.sshd.common.io.nio2.Nio2Session$1                  177 - Read 52 bytes
2014-12-22 15:07:22,231 []-nio2-thread-3] TRACE org.apache.sshd.common.session.AbstractSession                725 - Received packet #9: 61 00 00 00 00
2014-12-22 15:07:22,231 []-nio2-thread-3] DEBUG org.apache.sshd.common.channel.AbstractChannel                142 - Received SSH_MSG_CHANNEL_CLOSE on channel ChannelSession[id=0, recipient=0]
2014-12-22 15:07:22,247 [reader         ] DEBUG net.schmizz.sshj.transport.KeyExchanger                       379 - Got notified of net.schmizz.sshj.connection.ConnectionException: [PROTOCOL_ERROR] Received CHANNEL_SUCCESS on unknown channel #0
2014-12-22 15:07:22,247 [reader         ] DEBUG net.schmizz.sshj.AbstractService                               57 - Notified of net.schmizz.sshj.connection.ConnectionException: [PROTOCOL_ERROR] Received CHANNEL_SUCCESS on unknown channel #0
2014-12-22 15:07:22,247 []-nio2-thread-1] DEBUG org.apache.sshd.common.io.nio2.Nio2Session$2                  223 - Finished writing
2014-12-22 15:07:22,247 []-nio2-thread-3] DEBUG g.apache.sshd.common.util.CloseableUtils$AbstractCloseable$1  365 - ChannelSession[id=0, recipient=0] closed
2014-12-22 15:07:22,247 [reader         ] DEBUG net.schmizz.sshj.transport.TransportImpl                      283 - Setting active service to null-service
2014-12-22 15:07:22,247 [reader         ] DEBUG net.schmizz.sshj.transport.TransportImpl                      421 - Sending SSH_MSG_DISCONNECT: reason=[PROTOCOL_ERROR], msg=[Received CHANNEL_SUCCESS on unknown channel #0]
2014-12-22 15:07:22,247 [reader         ] TRACE net.schmizz.sshj.transport.Encoder                             80 - Encoding packet #8: 01 00 00 00 02 00 00 00 2e 52 65 63 65 69 76 65 64 20 43 48 41 4e 4e 45 4c 5f 53 55 43 43 45 53 53 20 6f 6e 20 75 6e 6b 6e 6f 77 6e 20 63 68 61 6e 6e 65 6c 20 23 30 00 00 00 00
2014-12-22 15:07:22,247 [reader         ] DEBUG net.schmizz.concurrent.Promise                                 78 - Setting <<transport close>> to `SOME`
2014-12-22 15:07:22,247 [reader         ] DEBUG net.schmizz.sshj.transport.Reader                              70 - Stopping
2014-12-22 15:07:22,247 []-nio2-thread-1] DEBUG org.apache.sshd.common.io.nio2.Nio2Session$1                  177 - Read 100 bytes
2014-12-22 15:07:22,247 []-nio2-thread-1] TRACE org.apache.sshd.common.session.AbstractSession                725 - Received packet #10: 01 00 00 00 02 00 00 00 2e 52 65 63 65 69 76 65 64 20 43 48 41 4e 4e 45 4c 5f 53 55 43 43 45 53 53 20 6f 6e 20 75 6e 6b 6e 6f 77 6e 20 63 68 61 6e 6e 65 6c 20 23 30 00 00 00 00
2014-12-22 15:07:22,247 []-nio2-thread-1] DEBUG org.apache.sshd.common.session.AbstractSession                305 - Received SSH_MSG_DISCONNECT (reason=2, msg=Received CHANNEL_SUCCESS on unknown channel #0)
2014-12-22 15:07:22,247 []-nio2-thread-1] DEBUG org.apache.sshd.common.util.CloseableUtils$AbstractCloseable  348 - Closing ServerSession[mli@/127.0.0.1:63822] immediately
2014-12-22 15:07:22,247 []-nio2-thread-1] DEBUG org.apache.sshd.common.util.CloseableUtils$AbstractCloseable  348 - Closing ServerConnectionService immediately
2014-12-22 15:07:22,247 []-nio2-thread-1] DEBUG org.apache.sshd.common.util.CloseableUtils$AbstractCloseable  348 - Closing org.apache.sshd.common.forward.DefaultTcpipForwarder@7b052786 immediately
2014-12-22 15:07:22,247 []-nio2-thread-1] DEBUG org.apache.sshd.common.util.CloseableUtils$AbstractCloseable  351 - org.apache.sshd.common.forward.DefaultTcpipForwarder@7b052786 closed
2014-12-22 15:07:22,247 []-nio2-thread-1] DEBUG org.apache.sshd.common.util.CloseableUtils$AbstractCloseable  348 - Closing org.apache.sshd.agent.common.AgentForwardSupport@5a40d55 immediately
2014-12-22 15:07:22,247 []-nio2-thread-1] DEBUG org.apache.sshd.common.util.CloseableUtils$AbstractCloseable  351 - org.apache.sshd.agent.common.AgentForwardSupport@5a40d55 closed
2014-12-22 15:07:22,247 []-nio2-thread-1] DEBUG org.apache.sshd.common.util.CloseableUtils$AbstractCloseable  351 - ServerConnectionService closed
2014-12-22 15:07:22,247 []-nio2-thread-1] DEBUG org.apache.sshd.common.util.CloseableUtils$AbstractCloseable  348 - Closing Nio2Session[local=/127.0.0.1:63821, remote=/127.0.0.1:63822] immediately
2014-12-22 15:07:22,247 []-nio2-thread-1] DEBUG org.apache.sshd.common.util.CloseableUtils$AbstractCloseable  353 - ServerSession[mli@/127.0.0.1:63822] is already closing
2014-12-22 15:07:22,247 []-nio2-thread-1] DEBUG org.apache.sshd.common.util.CloseableUtils$AbstractCloseable  351 - Nio2Session[local=/127.0.0.1:63821, remote=/127.0.0.1:63822] closed
2014-12-22 15:07:22,247 []-nio2-thread-1] DEBUG org.apache.sshd.common.util.CloseableUtils$AbstractCloseable  351 - ServerSession[mli@/127.0.0.1:63822] closed
2014-12-22 15:07:22,247 []-nio2-thread-1] DEBUG org.apache.sshd.common.io.nio2.Nio2Session$1                  191 - IoSession has been closed, stop reading


Any idea?

I see the server (Apache SSHD) receive SSH_MSG_CHANNEL_REQUEST(wantReply=true), send SSH_MSG_CHANNEL_DATA, SSH_MSG_CHANNEL_EOF, SSH_MSG_CHANNEL_REQUEST(exit-status), SSH_MSG_CHANNEL_CLOSE.

I see SSHJ send channel request for `exec`, receive CHANNEL_DATA, CHANNEL_EOF, CHANNEL_REQUEST(exit-status), CHANNEL_CLOSE.

SSHJ then receives a CHANNEL_SUCCESS, which it doesn't like. Even though it seems to have requested it with wantReply=true?

[Martin Lichtin]

Found an interesting discussion about this apparent protocol ambiguity:

http://comments.gmane.org/gmane.ietf.secsh/7003

In general, do you guys agree that sshj should be able to talk to an Apache Sshd server, not? (Imho, this should be an integration test).

[Jeroen van Erp]

I think SSHJ is correct here as is also argued in the thread you mention. We don't expect the CHANNEL_SUCCESS message after a CHANNEL_CLOSE is received.

Though the spec is dubious at best in this case. What would your suggestion be? 

Regards,

Jeroen

--
You received this message because you are subscribed to the Google Groups "sshj-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to sshj-users+...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.