Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[email protected] unhandled #237

Closed
TheConstructor opened this issue Mar 16, 2016 · 9 comments
Closed

[email protected] unhandled #237

TheConstructor opened this issue Mar 16, 2016 · 9 comments
Milestone
0.16.0

Comments

@TheConstructor
Copy link

According to this mail-thread clients may receive "[email protected]" after authentication. While OpenSSH-6.9-Release-Notes already list issues with Terra Term, it seems your software is also affected.

If net.schmizz.sshj.userauth.UserAuthImpl#handle is called post-auth with a GLOBAL_REQUEST like [email protected] it will simply throw a NullPointerException, if the message is received before currentMethod is set to null you get the following stack-trace:

Caused by: net.schmizz.sshj.userauth.UserAuthException: Exhausted available authentication methods
    at net.schmizz.sshj.SSHClient.auth(SSHClient.java:232) ~[sshj-0.15.0.jar:na]
    at net.schmizz.sshj.SSHClient.authPublickey(SSHClient.java:331) ~[sshj-0.15.0.jar:na]
    ...
            ... 3 common frames omitted
Caused by: net.schmizz.sshj.userauth.UserAuthException: Received SSH_MSG_UNIMPLEMENTED while exchanging keys
    at net.schmizz.sshj.userauth.UserAuthException$1.chain(UserAuthException.java:33) ~[sshj-0.15.0.jar:na]
    at net.schmizz.sshj.userauth.UserAuthException$1.chain(UserAuthException.java:26) ~[sshj-0.15.0.jar:na]
    at net.schmizz.concurrent.Promise.deliverError(Promise.java:95) ~[sshj-0.15.0.jar:na]
    at net.schmizz.sshj.userauth.UserAuthImpl.notifyError(UserAuthImpl.java:151) ~[sshj-0.15.0.jar:na]
    at net.schmizz.sshj.transport.TransportImpl.die(TransportImpl.java:597) ~[sshj-0.15.0.jar:na]
    at net.schmizz.sshj.transport.Reader.run(Reader.java:68) ~[sshj-0.15.0.jar:na]
Caused by: net.schmizz.sshj.transport.TransportException: Received SSH_MSG_UNIMPLEMENTED while exchanging keys
    at net.schmizz.sshj.transport.TransportImpl.gotUnimplemented(TransportImpl.java:574) ~[sshj-0.15.0.jar:na]
    at net.schmizz.sshj.transport.TransportImpl.handle(TransportImpl.java:506) ~[sshj-0.15.0.jar:na]
    at net.schmizz.sshj.transport.Decoder.decode(Decoder.java:107) ~[sshj-0.15.0.jar:na]
    at net.schmizz.sshj.transport.Decoder.received(Decoder.java:175) ~[sshj-0.15.0.jar:na]
    at net.schmizz.sshj.transport.Reader.run(Reader.java:60) ~[sshj-0.15.0.jar:na]

I am connecting against a OpenSSH_7.1p2-hpn14v10, OpenSSL 1.0.2f 28 Jan 2016 server on a raspberry pi. Distribution is Gentoo.

Strangely this error only occurs once every 5-10 connections. I used the debugger to verify it actually is a [email protected]-message.
@TheConstructor
Copy link
Author

And here is the mentioned NPE-variant:

Caused by: net.schmizz.sshj.connection.ConnectionException: null
    at net.schmizz.sshj.connection.ConnectionException$1.chain(ConnectionException.java:32) ~[sshj-0.15.0.jar:na]
    at net.schmizz.sshj.connection.ConnectionException$1.chain(ConnectionException.java:26) ~[sshj-0.15.0.jar:na]
    at net.schmizz.concurrent.Promise.deliverError(Promise.java:95) ~[sshj-0.15.0.jar:na]
    at net.schmizz.concurrent.Event.deliverError(Event.java:72) ~[sshj-0.15.0.jar:na]
    at net.schmizz.concurrent.ErrorDeliveryUtil.alertEvents(ErrorDeliveryUtil.java:34) ~[sshj-0.15.0.jar:na]
    at net.schmizz.sshj.connection.channel.AbstractChannel.notifyError(AbstractChannel.java:218) ~[sshj-0.15.0.jar:na]
    at net.schmizz.sshj.connection.channel.direct.SessionChannel.notifyError(SessionChannel.java:229) ~[sshj-0.15.0.jar:na]
    at net.schmizz.sshj.common.ErrorNotifiable$Util.alertAll(ErrorNotifiable.java:35) ~[sshj-0.15.0.jar:na]
    at net.schmizz.sshj.connection.ConnectionImpl.notifyError(ConnectionImpl.java:262) ~[sshj-0.15.0.jar:na]
    at net.schmizz.sshj.transport.TransportImpl.die(TransportImpl.java:597) ~[sshj-0.15.0.jar:na]
    at net.schmizz.sshj.transport.Reader.run(Reader.java:68) ~[sshj-0.15.0.jar:na]
Caused by: net.schmizz.sshj.common.SSHException: null
    at net.schmizz.sshj.common.SSHException$1.chain(SSHException.java:36) ~[sshj-0.15.0.jar:na]
    at net.schmizz.sshj.common.SSHException$1.chain(SSHException.java:29) ~[sshj-0.15.0.jar:na]
    at net.schmizz.sshj.transport.TransportImpl.die(TransportImpl.java:591) ~[sshj-0.15.0.jar:na]
    ... 1 common frames omitted
Caused by: java.lang.NullPointerException: null
    at net.schmizz.sshj.userauth.UserAuthImpl.handle(UserAuthImpl.java:134) ~[sshj-0.15.0.jar:na]
    at net.schmizz.sshj.transport.TransportImpl.handle(TransportImpl.java:490) ~[sshj-0.15.0.jar:na]
    at net.schmizz.sshj.transport.Decoder.decode(Decoder.java:107) ~[sshj-0.15.0.jar:na]
    at net.schmizz.sshj.transport.Decoder.received(Decoder.java:175) ~[sshj-0.15.0.jar:na]
    at net.schmizz.sshj.transport.Reader.run(Reader.java:60) ~[sshj-0.15.0.jar:na]

@TheConstructor
Copy link
Author

Work-arround: pick a client with SSH_BUG_HOSTKEYS in OpenSSH's compat.c and set it as Version on your Config:

SSH_CONFIG.setVersion("TeraTerm SSH - " + SSH_CONFIG.getVersion());

@hierynomus
Copy link
Owner

Can you send a debug log for both scenarios with the following levels:

    <logger name="net.schmizz.sshj" level="debug"/>
    <logger name="net.schmizz.sshj.transport" level="trace" />

@TheConstructor
Copy link
Author

If I left out important stuff, just ask. I'm not sure what is important and what just would give details about my application unreleted to this problem.

NPE-case:

    2016-03-18 14:28:52.882  INFO 42561 --- [pool-4-thread-1] n.schmizz.sshj.transport.TransportImpl   : Client identity string: SSH-2.0-SSHJ_0_14_0
    2016-03-18 14:28:53.113  INFO 42561 --- [pool-4-thread-1] n.schmizz.sshj.transport.TransportImpl   : Server identity string: SSH-2.0-OpenSSH_7.1p2-hpn14v10
    2016-03-18 14:28:53.113 DEBUG 42561 --- [pool-4-thread-1] net.schmizz.sshj.transport.KeyExchanger  : Sending SSH_MSG_KEXINIT
    2016-03-18 14:28:53.116 DEBUG 42561 --- [         reader] net.schmizz.sshj.transport.KeyExchanger  : Received SSH_MSG_KEXINIT
    2016-03-18 14:28:53.116 DEBUG 42561 --- [         reader] net.schmizz.sshj.transport.KeyExchanger  : Negotiated algorithms: [ [email protected]; sig=ecdsa-sha2-nistp256; c2sCipher=aes128-ctr; s2cCipher=aes128-ctr; c2sMAC=hmac-sha1; s2cMAC=hmac-sha1; c2sComp=none; s2cComp=none ]
    2016-03-18 14:28:53.117 DEBUG 42561 --- [         reader] n.s.sshj.transport.kex.Curve25519SHA256  : Sending SSH_MSG_KEXDH_INIT
    2016-03-18 14:28:53.338 DEBUG 42561 --- [         reader] net.schmizz.sshj.transport.KeyExchanger  : Received kex followup data
    2016-03-18 14:28:53.338 DEBUG 42561 --- [         reader] n.s.sshj.transport.kex.Curve25519SHA256  : Received SSH_MSG_KEXDH_REPLY

...

    2016-03-18 14:28:53.339 DEBUG 42561 --- [         reader] net.schmizz.sshj.transport.KeyExchanger  : Sending SSH_MSG_NEWKEYS
    2016-03-18 14:28:53.339 DEBUG 42561 --- [         reader] net.schmizz.sshj.transport.KeyExchanger  : Received SSH_MSG_NEWKEYS
    2016-03-18 14:28:53.340 DEBUG 42561 --- [pool-4-thread-1] net.schmizz.sshj.SSHClient               : Key exchange took 0.227 seconds
    2016-03-18 14:28:53.341 DEBUG 42561 --- [pool-4-thread-1] n.schmizz.sshj.transport.TransportImpl   : Sending SSH_MSG_SERVICE_REQUEST for ssh-userauth
    2016-03-18 14:28:53.344 DEBUG 42561 --- [pool-4-thread-1] n.schmizz.sshj.transport.TransportImpl   : Setting active service to ssh-userauth
    2016-03-18 14:28:53.344 DEBUG 42561 --- [pool-4-thread-1] net.schmizz.sshj.userauth.UserAuthImpl   : Trying `publickey` auth...
    2016-03-18 14:28:53.344 DEBUG 42561 --- [pool-4-thread-1] n.s.sshj.userauth.method.AuthPublickey   : Attempting 
    authentication using PKCS8KeyFile{resource=[PrivateKeyFileResource] ...}
    2016-03-18 14:28:53.425 DEBUG 42561 --- [         reader] net.schmizz.sshj.userauth.UserAuthImpl   : Asking `publickey` method to handle USERAUTH_60 packet
    2016-03-18 14:28:53.425 DEBUG 42561 --- [         reader] n.s.sshj.userauth.method.AuthPublickey   : Key acceptable, sending signed request
    2016-03-18 14:28:53.425 DEBUG 42561 --- [         reader] n.s.sshj.userauth.method.AuthPublickey   : Attempting 
    authentication using PKCS8KeyFile{resource=[PrivateKeyFileResource] ...}
    2016-03-18 14:28:53.824 DEBUG 42561 --- [pool-4-thread-1] net.schmizz.sshj.userauth.UserAuthImpl   : `publickey` auth successful
    2016-03-18 14:28:53.824 DEBUG 42561 --- [pool-4-thread-1] n.schmizz.sshj.transport.TransportImpl   : Setting active service to ssh-connection
    2016-03-18 14:28:53.824 DEBUG 42561 --- [pool-4-thread-1] n.s.sshj.connection.ConnectionImpl       : Attaching `session` channel (#0)
    2016-03-18 14:28:58.538 ERROR 42561 --- [         reader] n.schmizz.sshj.transport.TransportImpl   : Dying because - {}

    java.lang.NullPointerException: null
        at net.schmizz.sshj.userauth.UserAuthImpl.handle(UserAuthImpl.java:134) ~[sshj-0.15.0.jar:na]
        at net.schmizz.sshj.transport.TransportImpl.handle(TransportImpl.java:490) ~[sshj-0.15.0.jar:na]
        at net.schmizz.sshj.transport.Decoder.decode(Decoder.java:107) ~[sshj-0.15.0.jar:na]
        at net.schmizz.sshj.transport.Decoder.received(Decoder.java:175) ~[sshj-0.15.0.jar:na]
        at net.schmizz.sshj.transport.Reader.run(Reader.java:60) ~[sshj-0.15.0.jar:na]

    2016-03-18 14:28:58.538  INFO 42561 --- [         reader] n.schmizz.sshj.transport.TransportImpl   : Disconnected - UNKNOWN
    2016-03-18 14:28:58.538 DEBUG 42561 --- [         reader] net.schmizz.sshj.transport.KeyExchanger  : Got notified of net.schmizz.sshj.common.SSHException
    2016-03-18 14:28:58.539 DEBUG 42561 --- [         reader] n.s.sshj.connection.ConnectionImpl       : Notified of net.schmizz.sshj.common.SSHException
    2016-03-18 14:28:58.539 DEBUG 42561 --- [         reader] n.s.s.c.channel.direct.SessionChannel    : Channel #0 got notified of net.schmizz.sshj.common.SSHException
    2016-03-18 14:28:58.539 DEBUG 42561 --- [         reader] n.s.sshj.connection.ConnectionImpl       : Forgetting `session` channel (#0)
    2016-03-18 14:28:58.539 ERROR 42561 --- [pool-4-thread-1] net.schmizz.concurrent.Promise           : <<chan#0 / open>> woke to: net.schmizz.sshj.connection.ConnectionException
    2016-03-18 14:28:58.539 DEBUG 42561 --- [         reader] n.schmizz.sshj.transport.TransportImpl   : Setting active service to null-service
    2016-03-18 14:28:58.539 DEBUG 42561 --- [         reader] net.schmizz.sshj.transport.Reader        : Stopping
    2016-03-18 14:28:58.539 ERROR 42561 --- [     keep-alive] n.schmizz.sshj.transport.TransportImpl   : Dying because - {}

    java.lang.InterruptedException: sleep interrupted
        at java.lang.Thread.sleep(Native Method) ~[na:1.8.0_74]
        at net.schmizz.keepalive.KeepAlive.run(KeepAlive.java:66) ~[sshj-0.15.0.jar:na]

    2016-03-18 14:28:58.539  INFO 42561 --- [     keep-alive] n.schmizz.sshj.transport.TransportImpl   : Disconnected - UNKNOWN
    2016-03-18 14:28:58.539 DEBUG 42561 --- [     keep-alive] net.schmizz.sshj.transport.KeyExchanger  : Got notified of net.schmizz.sshj.common.SSHException: sleep interrupted
    2016-03-18 14:28:58.539 DEBUG 42561 --- [     keep-alive] n.s.s.t.TransportImpl$NullService        : Notified of net.schmizz.sshj.common.SSHException: sleep interrupted
    2016-03-18 14:28:58.539 DEBUG 42561 --- [     keep-alive] n.schmizz.sshj.transport.TransportImpl   : Setting active service to null-service

    java.util.concurrent.ExecutionException: net.schmizz.sshj.connection.ConnectionException
        ...
    Caused by: net.schmizz.sshj.connection.ConnectionException: null
        at net.schmizz.sshj.connection.ConnectionException$1.chain(ConnectionException.java:32) ~[sshj-0.15.0.jar:na]
        at net.schmizz.sshj.connection.ConnectionException$1.chain(ConnectionException.java:26) ~[sshj-0.15.0.jar:na]
        at net.schmizz.concurrent.Promise.deliverError(Promise.java:95) ~[sshj-0.15.0.jar:na]
        at net.schmizz.concurrent.Event.deliverError(Event.java:72) ~[sshj-0.15.0.jar:na]
        at net.schmizz.concurrent.ErrorDeliveryUtil.alertEvents(ErrorDeliveryUtil.java:34) ~[sshj-0.15.0.jar:na]
        at net.schmizz.sshj.connection.channel.AbstractChannel.notifyError(AbstractChannel.java:218) ~[sshj-0.15.0.jar:na]
        at net.schmizz.sshj.connection.channel.direct.SessionChannel.notifyError(SessionChannel.java:229) ~[sshj-0.15.0.jar:na]
        at net.schmizz.sshj.common.ErrorNotifiable$Util.alertAll(ErrorNotifiable.java:35) ~[sshj-0.15.0.jar:na]
        at net.schmizz.sshj.connection.ConnectionImpl.notifyError(ConnectionImpl.java:262) ~[sshj-0.15.0.jar:na]
        at net.schmizz.sshj.transport.TransportImpl.die(TransportImpl.java:597) ~[sshj-0.15.0.jar:na]
        at net.schmizz.sshj.transport.Reader.run(Reader.java:68) ~[sshj-0.15.0.jar:na]
    Caused by: net.schmizz.sshj.common.SSHException: null
        at net.schmizz.sshj.common.SSHException$1.chain(SSHException.java:36) ~[sshj-0.15.0.jar:na]
        at net.schmizz.sshj.common.SSHException$1.chain(SSHException.java:29) ~[sshj-0.15.0.jar:na]
        at net.schmizz.sshj.transport.TransportImpl.die(TransportImpl.java:591) ~[sshj-0.15.0.jar:na]
        ... 1 common frames omitted
    Caused by: java.lang.NullPointerException: null
        at net.schmizz.sshj.userauth.UserAuthImpl.handle(UserAuthImpl.java:134) ~[sshj-0.15.0.jar:na]
        at net.schmizz.sshj.transport.TransportImpl.handle(TransportImpl.java:490) ~[sshj-0.15.0.jar:na]
        at net.schmizz.sshj.transport.Decoder.decode(Decoder.java:107) ~[sshj-0.15.0.jar:na]
        at net.schmizz.sshj.transport.Decoder.received(Decoder.java:175) ~[sshj-0.15.0.jar:na]
        at net.schmizz.sshj.transport.Reader.run(Reader.java:60) ~[sshj-0.15.0.jar:na]

SSHException: Unexpected: SSH_MSG_UNIMPLEMENTED-Case:

    2016-03-18 14:36:05.729  INFO 42561 --- [pool-7-thread-1] n.schmizz.sshj.transport.TransportImpl   : Client identity string: SSH-2.0-SSHJ_0_14_0
    2016-03-18 14:36:05.821  INFO 42561 --- [pool-7-thread-1] n.schmizz.sshj.transport.TransportImpl   : Server identity string: SSH-2.0-OpenSSH_7.1p2-hpn14v10
    2016-03-18 14:36:05.821 DEBUG 42561 --- [pool-7-thread-1] net.schmizz.sshj.transport.KeyExchanger  : Sending SSH_MSG_KEXINIT
    2016-03-18 14:36:05.830 DEBUG 42561 --- [         reader] net.schmizz.sshj.transport.KeyExchanger  : Received SSH_MSG_KEXINIT
    2016-03-18 14:36:05.830 DEBUG 42561 --- [         reader] net.schmizz.sshj.transport.KeyExchanger  : Negotiated algorithms: [ [email protected]; sig=ecdsa-sha2-nistp256; c2sCipher=aes128-ctr; s2cCipher=aes128-ctr; c2sMAC=hmac-sha1; s2cMAC=hmac-sha1; c2sComp=none; s2cComp=none ]
    2016-03-18 14:36:05.830 DEBUG 42561 --- [         reader] n.s.sshj.transport.kex.Curve25519SHA256  : Sending SSH_MSG_KEXDH_INIT
    2016-03-18 14:36:05.917 DEBUG 42561 --- [         reader] net.schmizz.sshj.transport.KeyExchanger  : Received kex followup data
    2016-03-18 14:36:05.917 DEBUG 42561 --- [         reader] n.s.sshj.transport.kex.Curve25519SHA256  : Received SSH_MSG_KEXDH_REPLY
    2016-03-18 14:36:05.917 DEBUG 42561 --- [         reader] net.schmizz.sshj.common.KeyType$3        : Key algo: ecdsa-sha2-nistp256, Key curve: nistp256, Key Len: 65, 0x04: 4

...

    2016-03-18 14:36:07.745 DEBUG 42561 --- [         reader] net.schmizz.sshj.transport.KeyExchanger  : Sending SSH_MSG_NEWKEYS
    2016-03-18 14:36:07.745 DEBUG 42561 --- [         reader] net.schmizz.sshj.transport.KeyExchanger  : Received SSH_MSG_NEWKEYS
    2016-03-18 14:36:07.745 DEBUG 42561 --- [pool-7-thread-1] net.schmizz.sshj.SSHClient               : Key exchange took 0.23 seconds
    2016-03-18 14:36:07.746 DEBUG 42561 --- [pool-7-thread-1] n.schmizz.sshj.transport.TransportImpl   : Sending SSH_MSG_SERVICE_REQUEST for ssh-userauth
    2016-03-18 14:36:07.749 DEBUG 42561 --- [pool-7-thread-1] n.schmizz.sshj.transport.TransportImpl   : Setting active service to ssh-userauth
    2016-03-18 14:36:07.749 DEBUG 42561 --- [pool-7-thread-1] net.schmizz.sshj.userauth.UserAuthImpl   : Trying `publickey` auth...
    2016-03-18 14:36:07.749 DEBUG 42561 --- [pool-7-thread-1] n.s.sshj.userauth.method.AuthPublickey   : Attempting authentication using PKCS8KeyFile{resource=[PrivateKeyFileResource] ...}
    2016-03-18 14:36:07.832 DEBUG 42561 --- [         reader] net.schmizz.sshj.userauth.UserAuthImpl   : Asking `publickey` method to handle USERAUTH_60 packet
    2016-03-18 14:36:07.832 DEBUG 42561 --- [         reader] n.s.sshj.userauth.method.AuthPublickey   : Key acceptable, sending signed request
    2016-03-18 14:36:07.832 DEBUG 42561 --- [         reader] n.s.sshj.userauth.method.AuthPublickey   : Attempting authentication using PKCS8KeyFile{resource=[PrivateKeyFileResource] ...}
    2016-03-18 14:36:11.247 DEBUG 42561 --- [         reader] net.schmizz.sshj.userauth.UserAuthImpl   : Asking `publickey` method to handle GLOBAL_REQUEST packet
    2016-03-18 14:36:11.247 DEBUG 42561 --- [         reader] net.schmizz.sshj.transport.KeyExchanger  : Received SSH_MSG_KEXINIT
    2016-03-18 14:36:11.247 ERROR 42561 --- [pool-7-thread-1] net.schmizz.concurrent.Promise           : <<authenticated>> woke to: net.schmizz.sshj.userauth.UserAuthException: Unknown packet received during publickey auth: GLOBAL_REQUEST
    2016-03-18 14:36:11.247 DEBUG 42561 --- [         reader] net.schmizz.sshj.transport.KeyExchanger  : Sending SSH_MSG_KEXINIT
    2016-03-18 14:36:11.247 DEBUG 42561 --- [pool-7-thread-1] net.schmizz.sshj.userauth.UserAuthImpl   : Trying `publickey` auth...
    2016-03-18 14:36:11.247 DEBUG 42561 --- [pool-7-thread-1] n.s.sshj.userauth.method.AuthPublickey   : Attempting authentication using PKCS8KeyFile{resource=[PrivateKeyFileResource] ...}
    2016-03-18 14:36:11.247 DEBUG 42561 --- [         reader] net.schmizz.sshj.transport.KeyExchanger  : Negotiated algorithms: [ [email protected]; sig=ecdsa-sha2-nistp256; c2sCipher=aes128-ctr; s2cCipher=aes128-ctr; c2sMAC=hmac-sha1; s2cMAC=hmac-sha1; c2sComp=none; s2cComp=none ]
    2016-03-18 14:36:11.248 DEBUG 42561 --- [         reader] n.s.sshj.transport.kex.Curve25519SHA256  : Sending SSH_MSG_KEXDH_INIT
    2016-03-18 14:36:11.352 DEBUG 42561 --- [         reader] net.schmizz.sshj.transport.KeyExchanger  : Received kex followup data
    2016-03-18 14:36:11.352 DEBUG 42561 --- [         reader] n.s.sshj.transport.kex.Curve25519SHA256  : Received SSH_MSG_KEXDH_REPLY
    2016-03-18 14:36:11.352 DEBUG 42561 --- [         reader] net.schmizz.sshj.common.KeyType$3        : Key algo: ecdsa-sha2-nistp256, Key curve: nistp256, Key Len: 65, 0x04: 4
    x: [20, 108, 121, 78, 33, -20, -21, 59, -115, 6, -49, -14, -55, -88, 31, -103, -105, 3, -16, 105, 107, 46, 87, 44, 63, -79, 75, 87, 10, -100, 20, -62]
    y: [-83, -48, -49, 105, -117, 74, 7, 110, 29, 64, -101, 126, -7, -45, -61, 105, -7, -35, -104, 117, 74, -47, -77, 125, 16, -126, -128, -11, -90, 119, -53, 81]
    2016-03-18 14:36:11.353 DEBUG 42561 --- [         reader] net.schmizz.sshj.transport.KeyExchanger  : Trying to verify host key with net.schmizz.sshj.transport.verification.OpenSSHKnownHosts@190b87c5
    2016-03-18 14:36:11.353 DEBUG 42561 --- [         reader] net.schmizz.sshj.transport.KeyExchanger  : Trying to verify host key with net.schmizz.sshj.transport.verification.OpenSSHKnownHosts@17cc7a94
    2016-03-18 14:36:11.353 DEBUG 42561 --- [         reader] net.schmizz.sshj.transport.KeyExchanger  : Trying to verify host key with de.uni_muenster.cs.comsys.tbmgmt.experiment_control.support.SSHClientUtils$$Lambda$55/1535928681@556a8db4
    2016-03-18 14:36:11.354 DEBUG 42561 --- [         reader] net.schmizz.sshj.transport.KeyExchanger  : Sending SSH_MSG_NEWKEYS
    2016-03-18 14:36:11.354 DEBUG 42561 --- [         reader] net.schmizz.sshj.transport.KeyExchanger  : Received SSH_MSG_NEWKEYS
    2016-03-18 14:36:11.376 DEBUG 42561 --- [         reader] n.schmizz.sshj.transport.TransportImpl   : Received SSH_MSG_UNIMPLEMENTED #9
    2016-03-18 14:36:11.376 ERROR 42561 --- [         reader] n.schmizz.sshj.transport.TransportImpl   : Dying because - {}

    net.schmizz.sshj.common.SSHException: Unexpected: SSH_MSG_UNIMPLEMENTED
        at net.schmizz.sshj.AbstractService.notifyUnimplemented(AbstractService.java:63) ~[sshj-0.15.0.jar:na]
        at net.schmizz.sshj.transport.TransportImpl.gotUnimplemented(TransportImpl.java:575) ~[sshj-0.15.0.jar:na]
        at net.schmizz.sshj.transport.TransportImpl.handle(TransportImpl.java:506) ~[sshj-0.15.0.jar:na]
        at net.schmizz.sshj.transport.Decoder.decode(Decoder.java:107) ~[sshj-0.15.0.jar:na]
        at net.schmizz.sshj.transport.Decoder.received(Decoder.java:175) ~[sshj-0.15.0.jar:na]
        at net.schmizz.sshj.transport.Reader.run(Reader.java:60) ~[sshj-0.15.0.jar:na]

    2016-03-18 14:36:11.376  INFO 42561 --- [         reader] n.schmizz.sshj.transport.TransportImpl   : Disconnected - PROTOCOL_ERROR
    2016-03-18 14:36:11.376 DEBUG 42561 --- [         reader] net.schmizz.sshj.transport.KeyExchanger  : Got notified of net.schmizz.sshj.common.SSHException: [PROTOCOL_ERROR] Unexpected: SSH_MSG_UNIMPLEMENTED
    2016-03-18 14:36:11.376 DEBUG 42561 --- [         reader] net.schmizz.sshj.userauth.UserAuthImpl   : Notified of net.schmizz.sshj.common.SSHException: [PROTOCOL_ERROR] Unexpected: SSH_MSG_UNIMPLEMENTED
    2016-03-18 14:36:11.376 DEBUG 42561 --- [         reader] n.schmizz.sshj.transport.TransportImpl   : Setting active service to null-service
    2016-03-18 14:36:11.376 DEBUG 42561 --- [         reader] n.schmizz.sshj.transport.TransportImpl   : Sending SSH_MSG_DISCONNECT: reason=[PROTOCOL_ERROR], msg=[Unexpected: SSH_MSG_UNIMPLEMENTED]
    2016-03-18 14:36:11.377 ERROR 42561 --- [pool-7-thread-1] net.schmizz.concurrent.Promise           : <<authenticated>> woke to: net.schmizz.sshj.userauth.UserAuthException: Unexpected: SSH_MSG_UNIMPLEMENTED
    2016-03-18 14:36:11.377 DEBUG 42561 --- [         reader] net.schmizz.sshj.transport.Reader        : Stopping
    2016-03-18 14:36:11.377  INFO 42561 --- [pool-7-thread-1] n.schmizz.sshj.transport.TransportImpl   : Disconnected - BY_APPLICATION
    2016-03-18 14:36:11.377 DEBUG 42561 --- [pool-7-thread-1] n.s.s.t.TransportImpl$NullService        : Notified of net.schmizz.sshj.transport.TransportException: [BY_APPLICATION] Disconnected
    2016-03-18 14:36:11.377 DEBUG 42561 --- [pool-7-thread-1] n.schmizz.sshj.transport.TransportImpl   : Sending SSH_MSG_DISCONNECT: reason=[BY_APPLICATION], msg=[]
    2016-03-18 14:36:11.377 DEBUG 42561 --- [pool-7-thread-1] n.schmizz.sshj.transport.TransportImpl   : Error writing packet: net.schmizz.sshj.transport.TransportException: Socket closed
    2016-03-18 14:36:11.379  WARN 42561 --- [pool-3-thread-1] d.u.c.c.t.e.impl.ExperimentExecutor      : experiment: 39 -> Cancelling experiment 39 due to exception: java.util.concurrent.ExecutionException: net.schmizz.sshj.userauth.UserAuthException: Exhausted available authentication methods

    java.util.concurrent.ExecutionException: net.schmizz.sshj.userauth.UserAuthException: Exhausted available authentication methods
    ...
    Caused by: net.schmizz.sshj.userauth.UserAuthException: Exhausted available authentication methods
        at net.schmizz.sshj.SSHClient.auth(SSHClient.java:232) ~[sshj-0.15.0.jar:na]
        at net.schmizz.sshj.SSHClient.authPublickey(SSHClient.java:331) ~[sshj-0.15.0.jar:na]
        at de.uni_muenster.cs.comsys.tbmgmt.experiment_control.support.SSHClientUtils.clientFor(SSHClientUtils.java:112) ~[classes/:na]
        at de.uni_muenster.cs.comsys.tbmgmt.experiment_control.impl.ExperimentExecutor.getSSHClient(ExperimentExecutor.java:125) ~[classes/:na]
        at de.uni_muenster.cs.comsys.tbmgmt.experiment_control.impl.ExperimentExecutor.sftpConnectionTo(ExperimentExecutor.java:164) ~[classes/:na]
        at de.uni_muenster.cs.comsys.tbmgmt.experiment_control.impl.executionSteps.OutputEvaluator.lambda$0(OutputEvaluator.java:142) ~[classes/:na]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[na:1.8.0_74]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[na:1.8.0_74]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[na:1.8.0_74]
        ... 3 common frames omitted
    Caused by: net.schmizz.sshj.userauth.UserAuthException: Unexpected: SSH_MSG_UNIMPLEMENTED
        at net.schmizz.sshj.userauth.UserAuthException$1.chain(UserAuthException.java:33) ~[sshj-0.15.0.jar:na]
        at net.schmizz.sshj.userauth.UserAuthException$1.chain(UserAuthException.java:26) ~[sshj-0.15.0.jar:na]
        at net.schmizz.concurrent.Promise.deliverError(Promise.java:95) ~[sshj-0.15.0.jar:na]
        at net.schmizz.sshj.userauth.UserAuthImpl.notifyError(UserAuthImpl.java:151) ~[sshj-0.15.0.jar:na]
        at net.schmizz.sshj.transport.TransportImpl.die(TransportImpl.java:597) ~[sshj-0.15.0.jar:na]
        at net.schmizz.sshj.transport.Reader.run(Reader.java:68) ~[sshj-0.15.0.jar:na]
    Caused by: net.schmizz.sshj.common.SSHException: Unexpected: SSH_MSG_UNIMPLEMENTED
        at net.schmizz.sshj.AbstractService.notifyUnimplemented(AbstractService.java:63) ~[sshj-0.15.0.jar:na]
        at net.schmizz.sshj.transport.TransportImpl.gotUnimplemented(TransportImpl.java:575) ~[sshj-0.15.0.jar:na]
        at net.schmizz.sshj.transport.TransportImpl.handle(TransportImpl.java:506) ~[sshj-0.15.0.jar:na]
        at net.schmizz.sshj.transport.Decoder.decode(Decoder.java:107) ~[sshj-0.15.0.jar:na]
        at net.schmizz.sshj.transport.Decoder.received(Decoder.java:175) ~[sshj-0.15.0.jar:na]
        at net.schmizz.sshj.transport.Reader.run(Reader.java:60) ~[sshj-0.15.0.jar:na]

@TheConstructor
Copy link
Author

I would presume that you don't expect the server to send a message on it's own directly after the authentication is done and then it matters how far the process in net.schmizz.sshj.userauth.UserAuthImpl#authenticate runs before the transport-thread receives the message.

public boolean authenticate(String username, Service nextService, AuthMethod method, int timeoutMs)
        throws UserAuthException, TransportException {
    final boolean outcome;

    authenticated.lock();
    try {
        super.request(); // Request "ssh-userauth" service (if not already active)

        currentMethod = method;
        currentMethod.init(makeAuthParams(username, nextService));
        authenticated.clear();
        log.debug("Trying `{}` auth...", method.getName());
        currentMethod.request();
        outcome = authenticated.retrieve(timeoutMs, TimeUnit.MILLISECONDS);

        if (outcome) {
            log.debug("`{}` auth successful", method.getName());
            trans.setAuthenticated(); // So it can put delayed compression into force if applicable
            trans.setService(nextService); // We aren't in charge anymore, next service is
        } else {
            log.debug("`{}` auth failed", method.getName());
        }

    } finally {
        currentMethod = null;
        authenticated.unlock();
    }

    return outcome;
}

More common case seems to be the NPE as usually the locks prevent the transport-layer from passing the message unto currentMethod in time. I guess the easiest solution would be to make net.schmizz.sshj.userauth.UserAuthImpl#handle forward all requests to nextService once the authentication is done by flipping a switch in case USERAUTH_SUCCESS of UserAuthImpl#handle.

@hierynomus
Copy link
Owner

Hi @TheConstructor,

Yes, I was looking at the same piece of code, it seems like a nasty race condition, not the first one I've solved today ;). Thanks for attaching the logs.

@hierynomus hierynomus modified the milestone: 0.16.0 Mar 18, 2016
@hierynomus
Copy link
Owner

Hi @TheConstructor,

I think I've fixed this, could you see whether you can still reproduce this with a latest snapshot. I have unfortunately not had time yet to setup a testing box myself.

@hierynomus
Copy link
Owner

Ok, checked and verified with an Debian Stretch VM with OpenSSH 7.2p2. The fix fixes the race condition. Thanks for reporting this!

@TheConstructor
Copy link
Author

Thanks for fixing! Any idea when 0.16.0 will be released?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
0.16.0
Development

No branches or pull requests
2 participants
@hierynomus @TheConstructor